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=arch...@jab.org
