[MDEV-7484] Log Time not consistent with InnoDB errors nor with MySQL error log time format Created: 2015-01-21  Updated: 2015-06-01  Resolved: 2015-05-30

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0, 10.1
Fix Version/s: 10.1.5

Type: Bug Priority: Major
Reporter: Chris Calender (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 1
Labels: None


 Description   

After troubleshooting various InnoDB errors, we noticed there was a difference in the log time formats for the InnoDB errors versus the normal error log entries.

Here are 2 examples:

150114 16:12:31 [Note] InnoDB: Initializing buffer pool, size = 512.0M
150114 16:12:31 [Note] InnoDB: Completed initialization of buffer pool
150114 16:12:31 [Note] InnoDB: Highest supported file format is Barracuda.
150114 16:12:32 [Note] InnoDB: 128 rollback segment(s) are active.
150114 16:12:32 [Note] InnoDB: Waiting for purge to start
150114 16:12:32 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-70.0 started; log sequence number 8733880113
2015-01-14 16:12:32 7f552c9f8700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool
2015-01-14 16:12:32 7f552c9f8700 InnoDB: Cannot open './/ib_buffer_pool' for reading: No such file or directory
150114 16:12:32 [Note] Plugin 'FEEDBACK' is disabled.
150114 16:12:32 [ERROR] Failed to create a socket for IPv6 '::': errno: 97.
150114 16:12:32 [Note] Server socket created on IP: '0.0.0.0'.
150114 16:12:32 [Note] Event Scheduler: Loaded 0 events
150114 16:12:32 [Note] /usr/sbin/mysqld: ready for connections.

150115 19:05:14 [Note] InnoDB: Completed initialization of buffer pool
150115 19:05:14 [Note] InnoDB: Highest supported file format is Barracuda.
2015-01-15 19:05:15 468c  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
150115 19:05:15 [ERROR] InnoDB: Could not find a valid tablespace file for 'test/t'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
150115 19:05:15 [ERROR] InnoDB: Tablespace open failed for '"test"."t"', ignored.
150115 19:05:15 [Note] InnoDB: 128 rollback segment(s) are active.
150115 19:05:15 [Note] InnoDB: Waiting for purge to start

Long story short, we basically have "2015-01-15 19:05:15" versus "150115 19:05:15".

The former appears to be what should be correct. This will make reading the error log more consistent, more readable, and in line with how MySQL performs this, as of 5.6.8 or 5.6.9 (and how InnoDB internal errors were already handled). Being consistent will be better for error log parsers as well.

What needs to change in order to fix this are 2 lines in "sql/log.cc", in function "print_buffer_to_file()", lines 7954 and 7955.

One needs to replace this:

fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
        start->tm_year % 100,

With:

fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
        start->tm_year + 1900,

I would like for this to be my first MariaDB patch/code contribution, if accepted, and if possible!

However, I'm not sure what steps I need to take from here.

Here is my diff:

Here is DIFF output:

c:\mysql\mariadb-10.0.15\sql>diff log.cc log.cc.orig.cc
7954,7955c7954,7955
<   fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
<                 start->tm_year + 1900,
---
>   fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
>           start->tm_year % 100,

Btw, I also re-compiled MariaDB and tested, and it works great:

2015-01-16 22:53:24 [Note] Plugin 'FEEDBACK' is disabled.
2015-01-16 22:53:24 [Note] Server socket created on IP: '::'.
2015-01-16 22:53:24 [Note] Event Scheduler: Loaded 0 events
2015-01-16 22:53:24 [Note] mysqld: ready for connections.

Please advise what I need to do in order to have this be my first contribution.



 Comments   
Comment by Jan Lindström (Inactive) [ 2015-02-04 ]

While I like your change, it would make MariaDB error log incompatible to MySQL error log.

Comment by Will Fong [ 2015-02-04 ]

What if it was an option that someone could set?

Comment by Jan Lindström (Inactive) [ 2015-02-04 ]

Will, fine if there is some real need for it, then 10.1.x.

Comment by Chris Calender (Inactive) [ 2015-02-04 ]

Hi Jan,

You stated this:

"While I like your change, it would make MariaDB error log incompatible to MySQL error log."

However, MySQL did change the format of their error log, hence this request.

It was changed in MySQL 5.6.8 or 5.6.9.

Comment by Jan Lindström (Inactive) [ 2015-02-05 ]

Verifying the output

Comment by Chris Calender (Inactive) [ 2015-02-06 ]

Just wanted to add some MySQL outputs and extra info (I verified it uses the "old" method in 5.6.8, but it uses the new method in 5.6.9 forward).

From the 5.6.9 changelog:

mysqld now writes dates to the error log in ISO (YYYY-MM-DD hh:mm:ss) format. It also includes its process ID following the date. Thanks to Davi Arnaut for the patch. (Bug #56240, Bug #11763523)

http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-9.html

And here are the corresponding error log entries:

MySQL 5.6.8-rc

150206 12:13:36 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL server acts as a master and has his hostname changed!! Please use '--log-bin=chris-laptop-bin' to avoid this problem.
150206 12:13:36 [Note] Plugin 'FEDERATED' is disabled.
150206 12:13:37 [Note] InnoDB: The InnoDB memory heap is disabled
150206 12:13:37 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
150206 12:13:37 [Note] InnoDB: Compressed tables use zlib 1.2.3
150206 12:13:37 [Note] InnoDB: CPU does not support crc32 instructions
150206 12:13:37 [Note] InnoDB: Initializing buffer pool, size = 18.0M
150206 12:13:37 [Note] InnoDB: Completed initialization of buffer pool
150206 12:13:37 [Note] InnoDB: Highest supported file format is Barracuda.
150206 12:13:37 [Warning] InnoDB: Resizing redo log from 2*3072 to 2*320 pages, LSN=1625977
150206 12:13:37 [Warning] InnoDB: Starting to delete and rewrite log files.
150206 12:13:37 [Note] InnoDB: Setting log file .\ib_logfile101 size to 5 MB
150206 12:13:37 [Note] InnoDB: Setting log file .\ib_logfile1 size to 5 MB
150206 12:13:37 [Note] InnoDB: Renaming log file .\ib_logfile101 to .\ib_logfile0
150206 12:13:37 [Warning] InnoDB: New log files created, LSN=1625977
150206 12:13:37 [Note] InnoDB: 128 rollback segment(s) are active.
150206 12:13:37 [Note] InnoDB: Waiting for purge to start
150206 12:13:38 [Note] InnoDB: 1.2.8 started; log sequence number 1625977
150206 12:13:38 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 7d801c04-ae23-11e4-b7b8-089e01009f6a.
150206 12:13:38 [Note] Server hostname (bind-address): '*'; port: 3350
150206 12:13:38 [Note] IPv6 is available.
150206 12:13:38 [Note]   - '::' resolves to '::';
150206 12:13:38 [Note] Server socket created on IP: '::'.
150206 12:13:41 [Note] Event Scheduler: Loaded 0 events
150206 12:13:41 [Note] mysqld: ready for connections.
Version: '5.6.8-rc-log'  socket: ''  port: 3350  MySQL Community Server (GPL)
150206 12:14:05 [Note] mysqld: Normal shutdown

MySQL 5.6.9-rc

2013-03-05 20:13:26 5736 [Note] Plugin 'FEDERATED' is disabled.
2013-03-05 20:13:26 1b98 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2013-03-05 20:13:26 5736 [Note] InnoDB: The InnoDB memory heap is disabled
2013-03-05 20:13:26 5736 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2013-03-05 20:13:26 5736 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-03-05 20:13:26 5736 [Note] InnoDB: CPU does not support crc32 instructions
2013-03-05 20:13:26 5736 [Note] InnoDB: Initializing buffer pool, size = 96.0M
2013-03-05 20:13:26 5736 [Note] InnoDB: Completed initialization of buffer pool
2013-03-05 20:13:26 5736 [Note] InnoDB: Highest supported file format is Barracuda.
2013-03-05 20:13:27 5736 [Note] InnoDB: 128 rollback segment(s) are active.
2013-03-05 20:13:27 5736 [Note] InnoDB: Waiting for purge to start
2013-03-05 20:13:27 5736 [Note] InnoDB: 1.2.9 started; log sequence number 1613970
2013-03-05 20:13:27 5736 [Note] Server hostname (bind-address): '*'; port: 3309
2013-03-05 20:13:27 5736 [Note] IPv6 is available.
2013-03-05 20:13:27 5736 [Note]   - '::' resolves to '::';
2013-03-05 20:13:27 5736 [Note] Server socket created on IP: '::'.
2013-03-05 20:13:27 5736 [Note] Event Scheduler: Loaded 0 events
2013-03-05 20:13:27 5736 [Note] C:\Program Files\MySQL\MySQL Server 5.6\bin\mysqld: ready for connections.
Version: '5.6.9-rc'  socket: ''  port: 3309  MySQL Community Server (GPL)
2013-03-05 20:13:43 5736 [Note] C:\Program Files\MySQL\MySQL Server 5.6\bin\mysqld: Normal shutdown

MySQL 5.6.22

2015-02-05 13:33:25 4852 [Note] Plugin 'FEDERATED' is disabled.
2015-02-05 13:33:33 1310 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2015-02-05 13:33:33 4852 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-02-05 13:33:33 4852 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-05 13:33:33 4852 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2015-02-05 13:33:33 4852 [Note] InnoDB: Memory barrier is not used
2015-02-05 13:33:33 4852 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-05 13:33:33 4852 [Note] InnoDB: Not using CPU crc32 instructions
2015-02-05 13:33:34 4852 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2015-02-05 13:33:34 4852 [Note] InnoDB: Completed initialization of buffer pool
2015-02-05 13:33:38 4852 [Note] InnoDB: Highest supported file format is Barracuda.
2015-02-05 13:33:39 4852 [Note] InnoDB: The log sequence numbers 18771341574 and 18771341574 in ibdata files do not match the log sequence number 18771341584 in the ib_logfiles!
2015-02-05 13:33:39 4852 [Note] InnoDB: Database was not shutdown normally!
2015-02-05 13:33:39 4852 [Note] InnoDB: Starting crash recovery.
2015-02-05 13:33:39 4852 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-02-05 13:34:03 4852 [Note] InnoDB: Restoring possible half-written data pages 
2015-02-05 13:34:03 4852 [Note] InnoDB: from the doublewrite buffer...
2015-02-05 13:35:00 4852 [Note] InnoDB: 128 rollback segment(s) are active.
2015-02-05 13:35:00 4852 [Note] InnoDB: Waiting for purge to start
2015-02-05 13:35:00 4852 [Note] InnoDB: 5.6.22 started; log sequence number 18771341584
2015-02-05 13:35:01 4852 [Note] Server hostname (bind-address): '*'; port: 3309
2015-02-05 13:35:01 4852 [Note] IPv6 is available.
2015-02-05 13:35:01 4852 [Note]   - '::' resolves to '::';
2015-02-05 13:35:01 4852 [Note] Server socket created on IP: '::'.
2015-02-05 13:35:12 4852 [Note] Event Scheduler: Loaded 0 events
2015-02-05 13:35:12 4852 [Note] C:\Program Files\MySQL\MySQL Server 5.6\bin\mysqld: ready for connections.
Version: '5.6.22'  socket: ''  port: 3309  MySQL Community Server (GPL)

Fwiw, MySQL 5.5.41 uses the old method.

As for MySQL 5.7, I see the first version uses the new method (5.7.1):

MySQL 5.7.1

2013-06-13 18:43:00 2276 [Note] Plugin 'FEDERATED' is disabled.
2013-06-13 18:43:00 2276 [Warning] option 'innodb-autoextend-increment': unsigned value 67108864 adjusted to 1000
2013-06-13 18:43:00 2276 [Warning] InnoDB: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2013-06-13 18:43:00 2276 [Note] InnoDB: The InnoDB memory heap is disabled
2013-06-13 18:43:00 2276 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2013-06-13 18:43:00 2276 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-06-13 18:43:00 2276 [Warning] InnoDB: Adjusting innodb_buffer_pool_instances from 8 to 1 since innodb_buffer_pool_size is less than 1024 MiB
2013-06-13 18:43:00 2276 [Note] InnoDB: Not using CPU crc32 instructions
2013-06-13 18:43:00 2276 [Note] InnoDB: Initializing buffer pool, total size = 64.0M, instances = 1
2013-06-13 18:43:00 2276 [Note] InnoDB: Completed initialization of buffer pool
2013-06-13 18:43:00 2276 [Note] InnoDB: Highest supported file format is Barracuda.
2013-06-13 18:43:00 2276 [Note] InnoDB: Creating shared tablespace for temporary tables
2013-06-13 18:43:00 2276 [Note] InnoDB: Setting file ".\ibtmp1" size to 12 MB
2013-06-13 18:43:00 2276 [Note] InnoDB: Database physically writes the file full: wait ...
2013-06-13 18:43:01 2276 [Note] InnoDB: 128 rollback segment(s) are active.
2013-06-13 18:43:01 2276 [Note] InnoDB: Waiting for purge to start
2013-06-13 18:43:01 2276 [Note] InnoDB: 5.7.1 started; log sequence number 1626857

But, 5.7.2 uses an even different method (below is from 5.7.3):

MySQL 5.7.3

2014-01-29T05:14:09.329213Z 0 [Note] Plugin 'FEDERATED' is disabled.
2014-01-29T05:14:09.354214Z 0 [Warning] option 'innodb-autoextend-increment': unsigned value 67108864 adjusted to 1000
2014-01-29T05:14:10.055254Z 0 [Warning] InnoDB: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2014-01-29T05:14:10.132259Z 0 [Note] InnoDB: The InnoDB memory heap is disabled
2014-01-29T05:14:10.133259Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2014-01-29T05:14:10.135259Z 0 [Note] InnoDB: Uses system mutexes
2014-01-29T05:14:10.136259Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-01-29T05:14:10.137259Z 0 [Warning] InnoDB: Adjusting innodb_buffer_pool_instances from 8 to 1 since innodb_buffer_pool_size is less than 1024 MiB
2014-01-29T05:14:10.395274Z 0 [Note] InnoDB: Number of pools: 1
2014-01-29T05:14:10.622287Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2014-01-29T05:14:10.761295Z 0 [Note] InnoDB: Initializing buffer pool, total size = 64.0M, instances = 1
2014-01-29T05:14:10.778296Z 0 [Note] InnoDB: Completed initialization of buffer pool
2014-01-29T05:14:11.310326Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2014-01-29T05:14:17.762695Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2014-01-29T05:14:17.764695Z 0 [Note] InnoDB: Setting file ".\ibtmp1" size to 12 MB
2014-01-29T05:14:17.765695Z 0 [Note] InnoDB: Database physically writes the file full: wait ...
2014-01-29T05:14:18.484737Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2014-01-29T05:14:18.485737Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2014-01-29T05:14:18.760752Z 0 [Note] InnoDB: Waiting for purge to start
2014-01-29T05:14:18.823756Z 0 [Note] InnoDB: 5.7.3 started; log sequence number 7873246

From the 5.7.2 changelog:

The format of timestamps has changed for messages written to the error log, and for general query log and slow query log messages written to files. Timestamps are written using ISO 8601 / RFC 3339 format: YYYY-MM-DDThh:mm:ss.uuuuuu plus a tail value of Z signifying Zulu time (UTC) or ±hh:mm (an offset from UTC). In addition, for the general query log file, timestamps are included in every message, not just when the second changes

The format of timestamps has also changed for messages written to the general query log and slow query log tables (mysql.general_log, mysql.slow_log), which now include fractional seconds. (The column type for timestamps has changed from TIMESTAMP to TIMESTAMP(6).)"

http://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-2.html

And 2 other relevant changes in 5.7.2:

Previously, the ID included in error log messages was the mysqld process ID. Now the ID is that of the thread within mysqld responsible for writing the message. This is more informative with respect to which part of the server produced the message. It is also more consistent with general query log and slow query log messages, which include the connection thread ID.

The log_timestamps system variable has been introduced for control of the timestamp time zone of messages written to the error log, and of general query log and slow query log messages written to files. (It does not affect the time zone of general query log and slow query log messages written to log tables, but rows retrieved from those tables can be converted from the local system time zone to any desired time zone with CONVERT_TZ() or by setting the session time_zone system variable.

The default timestamp time zone is different now (UTC rather than the local system time zone). To restore the previous default, set log_timestamps=SYSTEM."

Perhaps 10.0 should get the patch I provided, whereas the latter, most recent changes in 5.7.2 should go into 10.1?

Hope this helps.

Comment by Chris Calender (Inactive) [ 2015-02-07 ]

Okay, given my findings above, I updated my fix to be this:

C:\mysql\mariadb-10.0.15\sql>diff log.cc log.cc.orig.cc
7954,7955c7954,7955
<   fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d %lu [%s] %.*s%.*s\n",
<                 start->tm_year + 1900,
---
>   fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
>           start->tm_year % 100,
7961d7960
<                 current_pid,

This changes the format and includes the process id, as MySQL 5.6 does.

Here is the output from newly built MariaDB instance:

2015-02-06 17:57:08 13920 [Warning] No argument was provided to -log-bin and neither -log-basename or --log-bin-index where used;  This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '-log-basename=chris-laptop' or '-log-bin=chris-laptop-bin' to avoid this problem.
2015-02-06 17:57:08 13920 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2015-02-06 17:57:08 13920 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-06 17:57:08 13920 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2015-02-06 17:57:08 13920 [Note] InnoDB: Memory barrier is not used
2015-02-06 17:57:08 13920 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-06 17:57:08 13920 [Note] InnoDB: Not using CPU crc32 instructions
2015-02-06 17:57:08 13920 [Note] InnoDB: Initializing buffer pool, size = 18.0M
2015-02-06 17:57:08 13920 [Note] InnoDB: Completed initialization of buffer pool
2015-02-06 17:57:08 13920 [Note] InnoDB: Highest supported file format is Barracuda.
2015-02-06 17:57:10 13920 [Warning] InnoDB: Resizing redo log from 2*3072 to 2*320 pages, LSN=1616697
2015-02-06 17:57:10 13920 [Warning] InnoDB: Starting to delete and rewrite log files.
2015-02-06 17:57:10 13920 [Note] InnoDB: Setting log file .\ib_logfile101 size to 5 MB
2015-02-06 17:57:10 13920 [Note] InnoDB: Setting log file .\ib_logfile1 size to 5 MB
2015-02-06 17:57:10 13920 [Note] InnoDB: Renaming log file .\ib_logfile101 to .\ib_logfile0
2015-02-06 17:57:10 13920 [Warning] InnoDB: New log files created, LSN=1616908
2015-02-06 17:57:10 13920 [Note] InnoDB: 128 rollback segment(s) are active.
2015-02-06 17:57:10 13920 [Note] InnoDB: Waiting for purge to start
2015-02-06 17:57:10 13920 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.21-70.0 started; log sequence number 1616697
2015-02-06 17:57:10 13920 [Note] Plugin 'FEEDBACK' is disabled.
2015-02-06 17:57:10 13920 [Note] Server socket created on IP: '::'.
2015-02-06 17:57:11 13920 [Note] Event Scheduler: Loaded 0 events
2015-02-06 17:57:11 13920 [Note] mysqld: ready for connections.
Version: '10.0.15-MariaDB-log'  socket: ''  port: 3351  Source distribution

And to compare, here is the latest output from a MySQL 5.6.22 instance:

2015-02-06 17:59:33 9476 [Note] Plugin 'FEDERATED' is disabled.
2015-02-06 17:59:33 2b50 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2015-02-06 17:59:33 9476 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-02-06 17:59:33 9476 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-06 17:59:33 9476 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2015-02-06 17:59:33 9476 [Note] InnoDB: Memory barrier is not used
2015-02-06 17:59:33 9476 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-02-06 17:59:33 9476 [Note] InnoDB: Not using CPU crc32 instructions
2015-02-06 17:59:33 9476 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2015-02-06 17:59:33 9476 [Note] InnoDB: Completed initialization of buffer pool
2015-02-06 17:59:33 9476 [Note] InnoDB: Highest supported file format is Barracuda.
2015-02-06 17:59:35 9476 [Note] InnoDB: 128 rollback segment(s) are active.
2015-02-06 17:59:35 9476 [Note] InnoDB: Waiting for purge to start
2015-02-06 17:59:35 9476 [Note] InnoDB: 5.6.22 started; log sequence number 18771341594

All in all, I feel my patch should be included in MariaDB 10.0 to get it on par with MySQL (but slightly improved because we still include the "tag" at the end, but just before the message.

As for the other changes in MySQL 5.7.2+, I propose those go into MariaDB 10.1. If you agree, I will create a different bug report for that, and can begin writing the patch for that also.

Comment by Jan Lindström (Inactive) [ 2015-02-09 ]

Patch :

=== modified file 'sql/log.cc'
--- sql/log.cc	2015-01-19 13:32:28 +0000
+++ sql/log.cc	2015-02-09 15:48:36 +0000
@@ -7952,13 +7952,14 @@
   localtime_r(&skr, &tm_tmp);
   start=&tm_tmp;
 
-  fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
-          start->tm_year % 100,
+  fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d %lu [%s] %.*s%.*s\n",
+          start->tm_year + 1900,
           start->tm_mon+1,
           start->tm_mday,
           start->tm_hour,
           start->tm_min,
           start->tm_sec,
+          current_pid,
           (level == ERROR_LEVEL ? "ERROR" : level == WARNING_LEVEL ?
            "Warning" : "Note"),
           tag_length, tag,

Comment by Jan Lindström (Inactive) [ 2015-02-09 ]

This produces output:

2015-02-09 17:55:11 4006 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2015-02-09 17:55:11 7f4e1c74f780 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2015-02-09 17:55:11 7f4e1c74f780 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!
!!!
2015-02-09 17:55:11 4006 [Note] InnoDB: The InnoDB memory heap is disabled
2015-02-09 17:55:11 4006 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-02-09 17:55:11 4006 [Note] InnoDB: Memory barrier is not used
2015-02-09 17:55:11 4006 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-02-09 17:55:11 4006 [Note] InnoDB: Using Linux native AIO
2015-02-09 17:55:11 4006 [Note] InnoDB: Using CPU crc32 instructions
2015-02-09 17:55:11 4006 [Note] InnoDB: Initializing buffer pool, size = 16.0M
2015-02-09 17:55:11 4006 [Note] InnoDB: Completed initialization of buffer pool
2015-02-09 17:55:11 4006 [Note] InnoDB: The first specified data file ./ibdata1 did 
not exist: a new database to be created!
2015-02-09 17:55:11 4006 [Note] InnoDB: Setting file ./ibdata1 size to 12 MB
2015-02-09 17:55:11 4006 [Note] InnoDB: Database physically writes the file full: wa
it...
2015-02-09 17:55:11 4006 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 
MB
2015-02-09 17:55:12 4006 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2015-02-09 17:55:14 4006 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_lo
gfile0
2015-02-09 17:55:14 4006 [Warning] InnoDB: New log files created, LSN=45781
2015-02-09 17:55:14 4006 [Note] InnoDB: Doublewrite buffer not found: creating new
2015-02-09 17:55:14 4006 [Note] InnoDB: Doublewrite buffer created
2015-02-09 17:55:15 4006 [Note] InnoDB: 128 rollback segment(s) are active.
2015-02-09 17:55:15 4006 [Warning] InnoDB: Creating foreign key constraint system ta
bles.
2015-02-09 17:55:15 4006 [Note] InnoDB: Foreign key constraint system tables created
2015-02-09 17:55:15 4006 [Note] InnoDB: Creating tablespace and datafile system tabl
es.
2015-02-09 17:55:15 4006 [Note] InnoDB: Tablespace and datafile system tables create
d.
2015-02-09 17:55:15 4006 [Note] InnoDB: Waiting for purge to start
2015-02-09 17:55:15 4006 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6
.22-71.0 started; log sequence number 0
2015-02-09 17:55:15 4006 [Note] Server socket created on IP: '::'.
2015-02-09 17:55:15 4006 [ERROR] Missing system table mysql.roles_mapping; please ru
n mysql_upgrade to create it
2015-02-09 17:55:15 4006 [Note] Event Scheduler: Loaded 0 events
2015-02-09 17:55:15 4006 [Warning] InnoDB: Cannot open table mysql/gtid_slave_pos fr
om the internal data dictionary of InnoDB though the .frm file for the table exists.
 See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html for how you 
can resolve the problem.
2015-02-09 17:55:15 4006 [Warning] Failed to load slave replication state from table
 mysql.gtid_slave_pos: 1932: Table 'mysql.gtid_slave_pos' doesn't exist in engine
2015-02-09 17:55:15 4006 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '10.0.17-MariaDB-debug'  socket: '/home/jan/mysql/db10/mysql.sock2'  port: 
3306  Source distribution

Comment by Daniel Black [ 2015-04-29 ]

From the comments of Jan ( https://github.com/MariaDB/server/pull/26#issuecomment-78431087 )

Perhaps the following could be cherry-picked in:

https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd

https://github.com/MariaDB/server/pull/26/files#diff-00fad7ccb1419e6cb1f05e3db6e76f06R126

https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd

Comment by Sergei Golubchik [ 2015-04-29 ]

I agree with danblack about removing second timestamp.

I don't like having a pid in the log, I cannot see what useful purpose it can serve. Having thread id is better. Or neither.

I think it's ok to fix innodb to use YYYY-MM-DD and to remove the second timestamp, but I wouldn't add a new column (pid or thread id) to the log in a GA release.

Perhaps it'd be safer to do all changes to log formats only in 10.1

Comment by Jan Lindström (Inactive) [ 2015-05-04 ]

Decided to do all changes to log formats only in 10.1

Comment by Jan Lindström (Inactive) [ 2015-05-22 ]

http://lists.askmonty.org/pipermail/commits/2015-May/007942.html

Comment by Jan Lindström (Inactive) [ 2015-05-30 ]

commit 59815a268b37a9859c31d6add4546f4c6a7ef6aa
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Fri May 22 08:24:59 2015 +0300

MDEV-7484: Log Time not consistent with InnoDB errors nor with MySQL error log time format

Generated at Thu Feb 08 07:19:56 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.