Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

A MySQL-server crashed here yesterday, and I'm not sure why (the most irritating kind of crash). The error log is full of Semaphore waits, but I don't know how to interpret most of it (<path> = /export/home/pb2/build/sb_0-3159149-1301580870.56/mysql-5.5.11/storage/innobase/, replaced to keep some sort of brevity). Load, cpu & memory consumption was negligible / normal during these errors:

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 1896
InnoDB: Warning: a long semaphore wait:
--Thread 140054051079936 has waited at <path>/btr/btr0cur.c line 1896 for 241.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
InnoDB: Warning: a long semaphore wait:
--Thread 140054255666944 has waited at <path>/row/row0sel.c line 3606 for 241.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
InnoDB: Warning: a long semaphore wait:
--Thread 140054294693632 has waited at <path>/row/row0sel.c line 2902 for 241.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
InnoDB: Warning: a long semaphore wait:
--Thread 140054005319424 has waited at <path>/btr/btr0sea.c line 1054 for 241.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
InnoDB: Warning: a long semaphore wait:
--Thread 140054272325376 has waited at <path>/trx/trx0trx.c line 208 for 241.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1

Last 3 lines repeated a bunch of times, after that I get 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
--Thread 140054306334464 has waited at <path>/trx/trx0trx.c line 353 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054310147840 has waited at <path>/trx/trx0trx.c line 1983 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054295697152 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054344120064 has waited at <path>/row/row0mysql.c line 2233 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054259681024 has waited at <path>/row/row0sel.c line 4708 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054009534208 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
--Thread 140054008129280 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054303323904 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
--Thread 140054308140800 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054293088000 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053984847616 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
--Thread 140054302119680 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054307337984 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
--Thread 140054270318336 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
--Thread 140053899802368 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
--Thread 140054307538688 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
--Thread 140060523423488 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
--Thread 140053988259584 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
--Thread 140054050076416 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
--Thread 140053885150976 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054007727872 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054051280640 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053661017856 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054306735872 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054020171520 has waited at <path>/trx/trx0trx.c line 700 for 243.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053914253056 has waited at <path>/trx/trx0trx.c line 700 for 242.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054335727360 has waited at <path>/srv/srv0srv.c line 2293 for 242.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053635929856 has waited at <path>/trx/trx0trx.c line 700 for 242.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053900805888 has waited at <path>/trx/trx0trx.c line 700 for 242.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053987858176 has waited at <path>/trx/trx0trx.c line 208 for 242.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054299109120 has waited at <path>/trx/trx0trx.c line 700 for 241.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054259881728 has waited at <path>/trx/trx0trx.c line 700 for 241.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054042851072 has waited at <path>/trx/trx0trx.c line 700 for 240.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053897594624 has waited at <path>/trx/trx0trx.c line 700 for 240.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140054269314816 has waited at <path>/trx/trx0trx.c line 700 for 228.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
--Thread 140053912647424 has waited at <path>/trx/trx0trx.c line 208 for 78.00 seconds the semaphore:
Mutex at 0x1276a68 created file <path>/srv/srv0srv.c line 1038, lock var 1
waiters flag 1
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
============================

After a couple of those (with of course increasing seconds in the semaphore wait, to a max of about 700), the MySQL process becomes unreachable (may be due to maxclients reached), and the only solution we could find which worked was just sending a kill -9 to the mysqld process.

Now, how do I actually interpret this InnoDB monitor output? Is it just a long/slow query which crashed the lot (and did not get written to the slow log due to the kill)? Other sources for the problem I should look into?

share|improve this question

1 Answer 1

sudo ipcs -s -c -p -t # will tell what semaphores are running
sudo ipcs -l # will tell limits are into the system    

do you have the slow query log on - if not try to have it on into my.cnf
[mysqld]
log-slow-queries=/path/log_slow
share|improve this answer
    
see what queries are showing up into the slow log and take it from there. –  silviud May 24 '11 at 18:12
    
Slow log was/is on, but rarely registers anything beyond 1 sec, with less then 0.01% in the stats. Unfortunately, because we had to brutally kill the server with kill -9 the slow queries that were running at that time were of course not logged. Will keep the ipcs in mind, if it happens in future I'll try to run it first before resorting to a hard restart. For now, resorting to a running daemon/connection which will log long queries showing up in information_schema.processlist during their run, might help the post-mortem next time it occurs. –  Wrikken May 25 '11 at 20:09

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.