Bug #69351 wrong process id shown when reporting loading or saving buffer pool ?
Submitted: 30 May 2013 8:19 Modified: 30 May 2013 14:48
Reporter: Simon Mudd (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S4 (Feature request)
Version:5.6.11 OS:Any
Assigned to: CPU Architecture:Any

[30 May 2013 8:19] Simon Mudd
Description:
I use this setting in /etc/my.cnf:

[root@myserver ~]# grep pool /etc/my.cnf
innodb_buffer_pool_load_at_startup  = 1
innodb_buffer_pool_dump_at_shutdown = 1

When shutting down the server I see:

...
2013-05-30 10:10:58 31448 [Note] InnoDB: FTS optimize thread exiting.
2013-05-30 10:10:58 31448 [Note] InnoDB: Starting shutdown...
2013-05-30 10:10:58 7fe6d9dca700 InnoDB: Dumping buffer pool(s) to .//ib_buffer_pool
2013-05-30 10:10:59 7fe6d9dca700 InnoDB: Buffer pool(s) dump completed at 130530 10:10:59
2013-05-30 10:11:05 31448 [Note] InnoDB: Shutdown completed; log sequence number 10000076700822
...

When I see mysql start up ( /etc/init.d/mysql start) I see:

2013-05-30 10:11:48 12580 [Note] InnoDB: 128 rollback segment(s) are active.
2013-05-30 10:11:48 12580 [Note] InnoDB: Waiting for purge to start
2013-05-30 10:11:48 12580 [Note] InnoDB: 5.6.11 started; log sequence number 10000076700822
2013-05-30 10:11:48 7f510a478700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool
2013-05-30 10:11:48 12580 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2013-05-30 10:11:48 12580 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2013-05-30 10:11:48 12580 [Note] Server socket created on IP: '0.0.0.0'.

12580 is the mysqld process id.
yet the "id" value which I'd expect to be a thread or process id shown " 7f510a478700 " appears to be something else. Is this value correct?

How to repeat:
See above.

Suggested fix:
This may not be a bug but looks a bit weird to me. AFAIK the linux thread ids are the same as the process ids and therefore are not normally shown as hex type numbers or generally that large.
[30 May 2013 9:05] Shane Bester
Background:
http://bugs.mysql.com/bug.php?id=56240
http://bazaar.launchpad.net/~mysql/mysql-server/5.6/revision/4461

The function ut_print_timestamp prints that information.
It uses the thread id instead of the process id.

Buffer pool dump and load is done in its own thread, buf_dump_thread,
so it has a different id.
[30 May 2013 13:38] Simon Mudd
Yes, that I understand but look at the formatting of the thread id. It should be as far as I can see a 64-bit unsigned number, yet is shown in hex not decimal as other "process ids". That strikes me as being inconsistent:

sql/log.cc uses: fprintf(stderr, "%d-%02d-%02d %02d:%02d:%02d %lu [%s] %.*s\n",
whereas storage/innobase/ut/ut0ut.cc uses: fprintf(file, "%d-%02d-%02d %02d:%02d:%02d %lx",

%lu (long unsigned) vs %lx (hex)

That's a trivial difference but just stands out as being "weird".