Description:
MySQL server occasionaly hangs and crashes every now and then (the intervals vary between 2 days and 4 weeks), each time with following report in error log:
2014-11-06_12:34:04.86073 InnoDB: Warning: a long semaphore wait:
2014-11-06_12:34:04.86152 --Thread 140246618216192 has waited at dict0dict.c line 771 for 241.00 seconds the semaphore:
2014-11-06_12:34:04.86154 Mutex at 0x7f93fb154c18 created file dict0dict.c line 725, lock var 1
2014-11-06_12:34:04.86155 waiters flag 1
This is followed by InnoDB monitor output, repeated several times and after 10 minutes server crashes itself:
2014-11-06_12:45:57.56876 InnoDB: ###### Diagnostic info printed to the standard error stream
2014-11-06_12:45:57.56879 InnoDB: Error: semaphore wait has lasted > 600 seconds
2014-11-06_12:45:57.56880 InnoDB: We intentionally crash the server, because it appears to be hung.
2014-11-06_12:45:57.56881 141106 13:45:57 InnoDB: Assertion failure in thread 140246642521856 in file srv0srv.c line 2502
2014-11-06_12:45:57.56881 InnoDB: We intentionally generate a memory trap.
The semaphores section of InnoDB monitor output shows following:
2014-11-06_12:34:21.19967 ----------
2014-11-06_12:34:21.19968 SEMAPHORES
2014-11-06_12:34:21.19968 ----------
2014-11-06_12:34:21.19970 OS WAIT ARRAY INFO: reservation count 1463345, signal count 320773040
2014-11-06_12:34:21.19971 --Thread 140246615205632 has waited at btr0sea.c line 633 for 257.00 seconds the semaphore:
2014-11-06_12:34:21.19971 X-lock (wait_ex) on RW-latch at 0x7f93fb14ed88 created in file btr0sea.c line 178
2014-11-06_12:34:21.19972 a writer (thread id 140246615205632) has reserved it in mode wait exclusive
2014-11-06_12:34:21.19972 number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
2014-11-06_12:34:21.19973 Last time read locked in file btr0sea.c line 882
2014-11-06_12:34:21.19974 Last time write locked in file /root/install/mysql-5.5-5.5.40/storage/innobase/btr/btr0sea.c line 633
2014-11-06_12:34:21.19974 --Thread 140246617413376 has waited at btr0cur.c line 1929 for 257.00 seconds the semaphore:
2014-11-06_12:34:21.19975 X-lock on RW-latch at 0x7f93fb14ed88 created in file btr0sea.c line 178
2014-11-06_12:34:21.19975 a writer (thread id 140246615205632) has reserved it in mode wait exclusive
2014-11-06_12:34:21.19976 number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
2014-11-06_12:34:21.19977 Last time read locked in file btr0sea.c line 882
2014-11-06_12:34:21.19977 Last time write locked in file /root/install/mysql-5.5-5.5.40/storage/innobase/btr/btr0sea.c line 633
2014-11-06_12:34:21.19978 --Thread 140246659307264 has waited at row0purge.c line 680 for 252.00 seconds the semaphore:
2014-11-06_12:34:21.19979 S-lock on RW-latch at 0x7f93d88829c0 created in file dict0dict.c line 738
2014-11-06_12:34:21.19979 a writer (thread id 140246617413376) has reserved it in mode exclusive
2014-11-06_12:34:21.19980 number of readers 0, waiters flag 1, lock_word: 0
2014-11-06_12:34:21.19981 Last time read locked in file row0upd.c line 149
2014-11-06_12:34:21.19981 Last time write locked in file /root/install/mysql-5.5-5.5.40/storage/innobase/row/row0mysql.c line 2806
2014-11-06_12:34:21.19982 --Thread 140246618216192 has waited at dict0dict.c line 771 for 258.00 seconds the semaphore:
2014-11-06_12:34:21.19982 Mutex at 0x7f93fb154c18 created file dict0dict.c line 725, lock var 1
2014-11-06_12:34:21.19983 waiters flag 1
2014-11-06_12:34:21.19983 --Thread 140246616610560 has waited at row0upd.c line 149 for 258.00 seconds the semaphore:
2014-11-06_12:34:21.19984 S-lock on RW-latch at 0x7f93d88829c0 created in file dict0dict.c line 738
2014-11-06_12:34:21.19985 a writer (thread id 140246617413376) has reserved it in mode exclusive
2014-11-06_12:34:21.19985 number of readers 0, waiters flag 1, lock_word: 0
2014-11-06_12:34:21.19986 Last time read locked in file row0upd.c line 149
2014-11-06_12:34:21.19986 Last time write locked in file /root/install/mysql-5.5-5.5.40/storage/innobase/row/row0mysql.c line 2806
2014-11-06_12:34:21.19987 --Thread 140246615406336 has waited at dict0dict.c line 351 for 258.00 seconds the semaphore:
2014-11-06_12:34:21.19988 Mutex at 0x7f93fb154c18 created file dict0dict.c line 725, lock var 1
2014-11-06_12:34:21.19989 waiters flag 1
2014-11-06_12:34:21.19989 Mutex spin waits 146633345, rounds 87075882, OS waits 444367
2014-11-06_12:34:21.19990 RW-shared spins 155918355, rounds 248504477, OS waits 648592
2014-11-06_12:34:21.19990 RW-excl spins 5878968, rounds 379134872, OS waits 300683
2014-11-06_12:34:21.19991 Spin rounds per wait: 0.59 mutex, 1.59 RW-shared, 64.49 RW-excl
This error first manifested on MySQL 5.6.17 several weeks after upgrade from MySQL 5.5 and persisted after update to 5.6.19. We attributed it to some error introduced in 5.6 release and after multiple crashes downgraded back to 5.5 (using mysqldump to produce SQL dumps of databases and importing them to fresh installation of MySQL 5.5.) The problem started appearing on 5.5 too however, as seen above.
I am adding snippet of the MySQL 5.6 error log:
2014-10-30_23:25:21.76903 --Thread 140476773140224 has waited at btr0cur.cc line 2020 for 245.00 seconds the semaphore:
2014-10-30_23:25:21.76904 X-lock (wait_ex) on RW-latch at 0x7fca3df31ce8 created in file btr0sea.cc line 173
2014-10-30_23:25:21.76905 a writer (thread id 140476773140224) has reserved it in mode wait exclusive
2014-10-30_23:25:21.76905 number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
2014-10-30_23:25:21.76906 Last time read locked in file btr0sea.cc line 338
2014-10-30_23:25:21.76907 Last time write locked in file /build/mysql-5.6-3mbIg4/mysql-5.6-5.6.19/storage/innobase/btr/btr0sea.cc line 658
To my eyes it seems the crash was caused by the same bug present on both 5.5 and 5.6. Most crashes happened during the night under high load (server was doing OPTIMIZE on its tables.)
After searching the archive of reported bugs, it seems this may be a duplicate of http://bugs.mysql.com/bug.php?id=73890 . Since I don't have enough expertise to be sure though, I'm posting this as separate entry.
How to repeat:
We were unable to reproduce the issue, nor we found anything common running in the database in all cases of server crash. As mentioned above, most crashes happened during night with server doing OPTIMIZE TABLE on its tables.
