MySQL 因长时间信号量等待而崩溃

MySQL 因长时间信号量等待而崩溃

昨天,一台 MySQL 服务器崩溃了,我不知道原因(最令人恼火的崩溃)。错误日志中充满了信号量等待,但我不知道如何解释其中的大部分(<path>= /export/home/pb2/build/sb_0-3159149-1301580870.56/mysql-5.5.11/storage/innobase/,替换为保持某种简洁性)。在发生这些错误期间,负载、CPU 和内存消耗可以忽略不计/正常:

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

最后 3 行重复了很多次,之后我得到了 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
============================

经过几次这样的情况之后(当然信号量等待时间也会增加,最多约为 700 秒),MySQL 进程变得无法访问(可能是由于达到了 maxclients ),我们能找到的唯一可行的解​​决方案就是kill -9向 mysqld 进程发送一个。

现在,我该如何解释这个 InnoDB 监视器输出?这是否只是一个导致大量崩溃的长/慢查询(并且由于终止而未写入慢日志)?我应该调查问题的其他来源?

答案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

相关内容