Connections all stuck waiting for semaphores

[Tim McCune]

We encountered a problem this morning in a production MySQL server where all of the connections got seemingly stuck waiting on semaphores.

5.1.63-0ubuntu0.10.04.1

We have never encountered this problem before in over 5 years of operation. We shut down MySQL, which took several minutes to complete. master-error.log showed 503 lines like this after 2 seconds:

130914 3:26:37 [Warning] /usr/sbin/mysqld: Forcing close of thread 247303 user: 'jboss'

Then we had to wait 6 more minutes for the shutdown to complete. When we restarted the server, it would not accept any connections. A look at master-error.log at this time showed that the database had apparently crashed during the 6-minute shutdown and the server was trying to recover, as we saw these lines:

130914 3:33:05 InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 238 2788038396
130914 3:33:05 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.

We then saw 9 minutes worth of output of lines like:

InnoDB: Rolling back of trx id 0 2288554632 completed
130914 3:42:34 InnoDB: Rolling back trx with id 0 2288554622, 2 rows to undo

and finally the log output stopped, but the server was still not accepting socket connections. Another shutdown of the database, again taking 6 minutes to complete, followed by another restart, which again showed

130914 3:54:53 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.

seemed to get the server back to a usable state where it was accepting connections again.

Looking at the output of SHOW ENGINE INNODB STATUS \G when the problem occurred, it looks like there are several threads that are stuck waiting on semaphores, but it is not at all clear to me what would have caused this problem to occur, or why MySQL was unable to stop without crashing after the problem occurred. Any insights would be appreciated. I attempted to paste the entire output of SHOW ENGINE INNODB STATUS here, but the forum told me "Please shorten your messages, the body is too large." So here is just the SEMAPHORES section:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 334026866, signal count 322155474
--Thread 139787989395216 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788009264912 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 165.00 seconds the semaphore:
S-lock on RW-latch at 0x7f230fbd2b48 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139787989395216) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787997423376 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 15.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788384470800 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787993007888 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787996219152 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787997222672 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788006655760 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 15.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787987187472 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788379252496 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787984979728 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788380055312 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788027930384 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788011071248 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787991602960 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 165.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787990599440 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 164.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787993810704 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788007257872 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139787988793104 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 15.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f558038 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788006655760) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788021708560 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 14.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787975747344 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 135.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787984377616 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788014483216 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788389488400 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788001638160 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788010870544 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788015286032 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 117.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787987990288 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 116.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788404741904 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 115.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788396713744 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 114.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787986183952 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 85.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788019701520 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 76.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788428076816 has waited at ../../../storage/innobase/log/log0log.c line 1973 for 3.00 seconds the semaphore:
S-lock on RW-latch at 0x7f2351831ad0 created in file ../../../storage/innobase/log/log0log.c line 794
a writer (thread id 139788428076816) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/log/log0log.c line 1973
Last time write locked in file ../../../storage/innobase/log/log0log.c line 1773
--Thread 139788373833488 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 66.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230ff1f408 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139787990599440) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788001838864 has waited at ../../../storage/innobase/trx/trx0trx.c line 1862 for 66.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788005050128 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 65.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f6f68f8 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788011071248) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/buf/buf0flu.c line 660
Last time write locked in file ../../../storage/innobase/btr/btr0sea.c line 794
--Thread 139788398118672 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 66.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788025923344 has waited at ../../../storage/innobase/trx/trx0undo.c line 1684 for 65.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788027328272 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 65.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230f6f68f8 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139788011071248) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/buf/buf0flu.c line 660
Last time write locked in file ../../../storage/innobase/btr/btr0sea.c line 794
--Thread 139788026726160 has waited at ../../../storage/innobase/include/btr0btr.ic line 28 for 65.00 seconds the semaphore:
S-lock on RW-latch at 0x7f230e6e7868 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139787987187472) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/include/btr0btr.ic line 28
Last time write locked in file ../../../storage/innobase/btr/btr0pcur.c line 249
--Thread 139788394506000 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 65.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230fbd2b48 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139787989395216) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788391094032 has waited at ../../../storage/innobase/btr/btr0cur.c line 463 for 65.00 seconds the semaphore:
X-lock on RW-latch at 0x7f230fbd2b48 created in file ../../../storage/innobase/buf/buf0buf.c line 550
a writer (thread id 139787989395216) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file ../../../storage/innobase/btr/btr0cur.c line 463
Last time write locked in file ../../../storage/innobase/btr/btr0cur.c line 463
--Thread 139788007659280 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 64.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787986585360 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 64.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788028733200 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 64.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139787992004368 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 64.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788004849424 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 64.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788001036048 has waited at ../../../storage/innobase/trx/trx0trx.c line 766 for 63.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788012074768 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 36.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
--Thread 139788391696144 has waited at ../../../storage/innobase/trx/trx0roll.c line 921 for 35.00 seconds the semaphore:
Mutex at 0x7f23518408c0 created file ../../../storage/innobase/trx/trx0rseg.c line 147, lock var 1
waiters flag 1
Mutex spin waits 0, rounds 8657765803, OS waits 93751386
RW-shared spins 270563779, OS waits 131129826; RW-excl spins 173329134, OS waits 89525637

Thanks.



Edited 1 time(s). Last edit at 09/15/2013 11:51PM by Tim McCune.