MySQL falha com longa espera de semáforo

Question

Um servidor MySQL caiu aqui ontem, e não sei por que (o tipo mais irritante de travamento). O log de erros está cheio de Semaphore espera, mas não sei como interpretar a maior parte ( <path> = /export/home/pb2/build/sb_0-3159149-1301580870.56/mysql-5.5.11/storage/innobase/ , substituído para manter algum tipo de brevidade). Carregar, cpu & o consumo de memória foi insignificante / normal durante esses erros:

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

Última 3 linhas repetidas várias vezes, depois eu recebo a saída do monitor InnoDB:

=====================================
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
============================

Depois de alguns (com o aumento dos segundos no semáforo esperar, até um máximo de cerca de 700), o processo do MySQL torna-se inacessível (pode ser devido a maxclients atingidos), e a única solução que encontramos estava apenas enviando um kill -9 para o processo mysqld.

Agora, como interpreto essa saída do monitor InnoDB? É apenas uma longa / lenta consulta que caiu o lote (e não foi escrito para o log lento devido ao matar)? Outras fontes para o problema que eu deveria investigar?

    

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