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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0(EOL), 10.1(EOL)
Fix Version/s: 10.1.5
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
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.

Attachments

Activity

Ascending order - Click to sort in descending order

Chris Calender (Inactive) created issue - 2015-01-21 02:53

Jan Lindström (Inactive) made changes - 2015-02-03 16:54

Field	Original Value	New Value
Assignee		Jan Lindström [ jplindst ]

Jan Lindström (Inactive) added a comment - 2015-02-04 09:49

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

Jan Lindström (Inactive) added a comment - 2015-02-04 09:49 While I like your change, it would make MariaDB error log incompatible to MySQL error log.

Jan Lindström (Inactive) made changes - 2015-02-04 09:49

Component/s		OTHER [ 10125 ]
Fix Version/s		N/A [ 14700 ]
Resolution		Won't Fix [ 2 ]
Status	Open [ 1 ]	Closed [ 6 ]

Will Fong added a comment - 2015-02-04 10:12

What if it was an option that someone could set?

Will Fong added a comment - 2015-02-04 10:12 What if it was an option that someone could set?

Jan Lindström (Inactive) added a comment - 2015-02-04 10:34

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

Jan Lindström (Inactive) added a comment - 2015-02-04 10:34 Will, fine if there is some real need for it, then 10.1.x.

Chris Calender (Inactive) added a comment - 2015-02-04 16:30

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.

Chris Calender (Inactive) added a comment - 2015-02-04 16:30 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.

Jan Lindström (Inactive) added a comment - 2015-02-05 15:22

Verifying the output

Jan Lindström (Inactive) added a comment - 2015-02-05 15:22 Verifying the output

Jan Lindström (Inactive) made changes - 2015-02-05 15:22

Resolution	Won't Fix [ 2 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Chris Calender (Inactive) added a comment - 2015-02-06 19:28 - edited

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 23072 to 2320 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.

Chris Calender (Inactive) added a comment - 2015-02-06 19:28 - edited 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.

Chris Calender (Inactive) added a comment - 2015-02-07 01:05 - edited

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.

Chris Calender (Inactive) added a comment - 2015-02-07 01:05 - edited 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.

Jan Lindström (Inactive) made changes - 2015-02-09 09:01

Fix Version/s		10.0.17 [ 18300 ]
Fix Version/s	N/A [ 14700 ]

Jan Lindström (Inactive) made changes - 2015-02-09 16:20

Status

Stalled [ 10000 ]

In Progress [ 3 ]

Jan Lindström (Inactive) added a comment - 2015-02-09 17:49

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,

Jan Lindström (Inactive) added a comment - 2015-02-09 17:49 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,

Jan Lindström (Inactive) added a comment - 2015-02-09 17:56

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

Jan Lindström (Inactive) added a comment - 2015-02-09 17:56 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

Jan Lindström (Inactive) made changes - 2015-02-09 17:56

Assignee	Jan Lindström [ jplindst ]	Sergei Golubchik [ serg ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Jan Lindström (Inactive) made changes - 2015-02-09 17:58

Issue Type

Task [ 3 ]

Bug [ 1 ]

Jan Lindström (Inactive) made changes - 2015-02-24 16:20

Affects Version/s

10.0 [ 16000 ]

Sergei Golubchik made changes - 2015-02-28 14:55

Fix Version/s		10.0 [ 16000 ]
Fix Version/s	10.0.17 [ 18300 ]

Sergei Golubchik made changes - 2015-03-05 21:24

Priority

Trivial [ 5 ]

Major [ 3 ]

Sergei Golubchik made changes - 2015-04-28 17:26

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. :)

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:
{noformat}
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.
{noformat}
{noformat}
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
{noformat}

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:
{code}
fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
start->tm_year % 100,
{code}
With:
{code}
fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
start->tm_year + 1900,
{code}

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:
{noformat}
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,
{noformat}
Btw, I also re-compiled MariaDB and tested, and it works great:
{noformat}
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.
{noformat}

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

Daniel Black added a comment - 2015-04-29 11:01

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

Daniel Black added a comment - 2015-04-29 11:01 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

Sergei Golubchik added a comment - 2015-04-29 16:45 - edited

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

Sergei Golubchik added a comment - 2015-04-29 16:45 - edited 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

Sergei Golubchik made changes - 2015-04-29 16:46

Assignee	Sergei Golubchik [ serg ]	Jan Lindström [ jplindst ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Jan Lindström (Inactive) made changes - 2015-05-04 09:11

Affects Version/s

10.1 [ 16100 ]

Jan Lindström (Inactive) made changes - 2015-05-04 09:11

Fix Version/s		10.1 [ 16100 ]
Fix Version/s	10.0 [ 16000 ]

Jan Lindström (Inactive) added a comment - 2015-05-04 09:11

Decided to do all changes to log formats only in 10.1

Jan Lindström (Inactive) added a comment - 2015-05-04 09:11 Decided to do all changes to log formats only in 10.1

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:51

Workflow

MariaDB v2 [ 59310 ]

MariaDB v3 [ 65207 ]

Jan Lindström (Inactive) added a comment - 2015-05-22 08:27

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

Jan Lindström (Inactive) added a comment - 2015-05-22 08:27 http://lists.askmonty.org/pipermail/commits/2015-May/007942.html

Jan Lindström (Inactive) made changes - 2015-05-22 08:27

Assignee	Jan Lindström [ jplindst ]	Sergei Golubchik [ serg ]
Status	Stalled [ 10000 ]	In Review [ 10002 ]

Sergei Golubchik made changes - 2015-05-29 13:09

Assignee	Sergei Golubchik [ serg ]	Jan Lindström [ jplindst ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Jan Lindström (Inactive) added a comment - 2015-05-30 20:55

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

Jan Lindström (Inactive) added a comment - 2015-05-30 20:55 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

Jan Lindström (Inactive) made changes - 2015-05-30 20:55

Component/s		Storage Engine - InnoDB [ 10129 ]
Component/s		Storage Engine - XtraDB [ 10135 ]
Fix Version/s		10.1.5 [ 18813 ]
Fix Version/s	10.1 [ 16100 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2015-06-01 01:45

Component/s

OTHER [ 10125 ]

Sergei Golubchik made changes - 2021-12-06 21:41

Workflow

MariaDB v3 [ 65207 ]

MariaDB v4 [ 148731 ]

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Chris Calender (Inactive)

Votes:: 1 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2015-01-21 02:53

Updated:: 2015-06-01 01:45

Resolved:: 2015-05-30 20:55

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Activity

People

Dates

Git Integration