Description:
InnoDB will print out its monitor information to error log when a long semaphore wait happens. This is necessary to diagnose crashes due to too-long semaphore waits, but many times we lack information about threads; For example:
--Thread 139640294078208 has waited at row0mysql.cc line 2990 for 249.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28b5bac518 created in file dict0dict.cc line 1198
a writer (thread id 139602339800832) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0mysql.cc line 2990
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary/label_exp/centos6-64_static/rpmbuild/BUILD/percona-server-5.7.18-15/percona-server-5.7.18-15/storage/innobase/dict/dict0stats.cc line 2375
A quick search for the writer holding the latch shows only the following:
grep 139602339800832 mysql.log |uniq -c
1624 a writer (thread id 139602339800832) has reserved it in mode exclusive
And it does not show up in hex either:
printf "%x" 139602339800832
7ef7b3dfa700
grep --count 7ef7b3dfa700 mysql.log
0
So unless we capture performance_schema.threads sample perpetually, we won't be able to tell what thread 139602339800832 was truly doing (the stall in this case was saving dict stats, but what operation was calling dict_stats_save() is what we need to know).
I reckon the sample comes from Percona Server but it totally applies to Community MySQL.
Hope the FR makes sense!
How to repeat:
Induce long semaphore waits and check if all threads mentioned in the SEMAPHORES section of InnoDB Monitor can be identified.
Suggested fix:
Dump contents of performance_schema.threads in the error log, along the InnoDB Monitor output.
