Hi all,

yesterday the mysql process on a database server became totallly unresponsive
after some long semaphore waits (load/cpu/memory were OK, as were all other
processes). The debug output started with this:

InnoDB: Warning: a long semaphore wait:
--Thread 140054029002496 has waited at <path>/btr/btr0sea.c line 631 for
241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x78733f8 created in file <path>/btr/btr0sea.c
line 182
a writer (thread id 140054029002496) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file <path>/btr/btr0sea.c line 879
Last time write locked in file <path>/btr/btr0cur.c line 189

.... followed by a bunch of other threads waiting for the same lock locked by
140054029002496

Version is 5.5.11.

I may be wrong here, but I tend to interpret this as '140054029002496' is
trying to get an exclusive lock on 0x78733f8, on which it already has an
exclusive lock, and hence is deadlocked in some manner. Am I right there? How
can this happen?

I certainly cannot reproduce a query which causes this, and I had to kill -9
the process, so nothing no running/long queries were written to the slow-query
log. (On a side note: not even root / superuser could connect to the MySQL
instance, so there was no way to check which queries were actually running) If
not, what should I look for in trying to determine the cause? (Added some
extra monitor output below sig in case it's needed).

Thanks,
--
Rik Wasmus

Some more InnoDB Monitor Output:

====================================110523 19:19:05 INNODB MONITOR OUTPUT
====================================Per second averages calculated from the last 45 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1661111 1_second, 1661102 sleeps, 166100 10_second,
429 background, 413 flush
srv_master_thread log flush and writes: 1662059
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3952510, signal count 31019262
--Thread 140054029002496 has waited at <path>/btr/btr0sea.c line 631 for
243.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x78733f8 created in file <path>/btr/btr0sea.c
line 182
a writer (thread id 140054029002496) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file <path>/btr/btr0sea.c line 879
Last time write locked in file <path>/btr/btr0cur.c line 1896
--Thread 140054051079936 has waited at <path>/btr/btr0cur.c line 1896 for
243.00 seconds the semaphore:
X-lock on RW-latch at 0x78733f8 created in file <path>/btr/btr0sea.c line 182
a writer (thread id 140054029002496) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file <path>/btr/btr0sea.c line 879
Last time write locked in file <path>/btr/btr0cur.c line 1896
--Thread 140054255666944 has waited at <path>/row/row0sel.c line 3606 for
243.00 seconds the semaphore:
S-lock on RW-latch at 0x78733f8 created in file <path>/btr/btr0sea.c line 182
a writer (thread id 140054029002496) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file <path>/btr/btr0sea.c line 879
Last time write locked in file <path>/btr/btr0cur.c line 1896
--Thread 140054294693632 has waited at <path>/row/row0sel.c line 2902 for
243.00 seconds the semaphore:
S-lock on RW-latch at 0x7f60fa5b7f40 created in file <path>/buf/buf0buf.c line
898
a writer (thread id 140054051079936) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file <path>/row/row0sel.c line 2902
Last time write locked in file <path>/row/row0upd.c line 2131
--Thread 140054005319424 has waited at <path>/btr/btr0sea.c line 1054 for
243.00 seconds the semaphore:
S-lock on RW-latch at 0x78733f8 created in file <path>/btr/btr0sea.c line 182
a writer (thread id 140054029002496) has reserved it in mode wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file <path>/btr/btr0sea.c line 879
Last time write locked in file <path>/btr/btr0cur.c line 1896
--Thread 140054272325376 has waited at <path>/trx/trx0trx.c line 208 for
243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1

<SNIP about +/- 35 identical errors/waits>

Mutex spin waits 117851637, rounds 89989545, OS waits 249362
RW-shared spins 11452811, rounds 158361139, OS waits 2122101
RW-excl spins 5229822, rounds 128114865, OS waits 1176460
Spin rounds per wait: 0.76 mutex, 13.83 RW-shared, 24.50 RW-excl
FAIL TO OBTAIN KERNEL MUTEX, SKIP LOCK INFO PRINTING
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
9947500 OS file reads, 105696752 OS file writes, 98371237 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 68, free list len 3667, seg size 3736, 997096 merges
merged operations:
insert 1421280, delete mark 897892, delete 86296
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 6375023, node heap has 13494 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 113572832858
Log flushed up to 113572832858
Last checkpoint at 113568853883
0 pending log writes, 0 pending chkp writes
95703706 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 3296722944; in additional pool allocated 0
Dictionary memory allocated 515016
Buffer pool size 196607
Free buffers 0
Database pages 183112
Old database pages 67574
Modified db pages 1548
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 30254129, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 9947464, created 56336, written 8910159
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 183112, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
26 queries inside InnoDB, 0 queries in queue
3 read views open inside InnoDB
Main thread process no. 11983, id 140054344120064, state: doing background
drop tables
Number of rows inserted 2622442, updated 21677630, deleted 504511, read
297438002948
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
========================= --
MySQL General Mailing List
For list archives: http://lists.mysql.com/mysql
To unsubscribe: http://lists.mysql.com/mysql?unsub=listsearcharchive@lassosoft.com