五一当天,公司下午2点,数据库的机器突然访问不了。应用不能访问了。客户无法使用!客服同志打电话通知,我当时在外面陪女儿玩,周边没有电脑。为了应付紧急状况,马上重启了机器。重启后可以使用了。具体什么原因导致这一的现象还要仔细分析。


第一步,找出宕机半个小时之内的CPU,内存,网络等检测数据!检测结果是这样的:

wKioL1cnB1LQ4vTHAAQ4d3NFlTs276.jpg

wKioL1cnB1PxUV-9AAKOcIX1gaU565.jpg

wKiom1cnBoPhztBbAAHPZoAYU0s640.jpg

wKiom1cnBoSSlXofAAHdbzcHYrs504.jpg

wKiom1cnCRHRjvI0AAC7oxNbUoE219.png

wKioL1cnFHKSYl7LAACYCNNgk_0860.png

从上面四个图可以看出,内存和网络正常,只有CPU从13:50开始一直使用过高,突然增长到90%!


由此分析出

原因一,Query查询响应过慢,也就是个别查询占用时间太长。

原因二,磁盘出问题

或许还有其他原因,目前还没经验分析出来


第二步,我接到电话后赶紧在附近找了一个商务中心,借了一台电脑,登陆到了首都在线的云端,查看mysql数据库机器的日志,昨天13:50左右出现了这样一段日志:

InnoDB: Warning: a long semaphore wait:
--Thread 140157120059136 has waited at lock0lock.cc line 6837 for 289.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140157120661248 has waited at trx0trx.cc line 1195 for 290.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: Warning: a long semaphore wait:
--Thread 140161374390016 has waited at trx0sys.ic line 431 for 290.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: Warning: a long semaphore wait:
--Thread 140161383220992 has waited at trx0trx.cc line 193 for 272.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: Warning: a long semaphore wait:
--Thread 140161379407616 has waited at trx0trx.cc line 863 for 271.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: Warning: a long semaphore wait:
--Thread 140157120259840 has waited at trx0trx.cc line 2013 for 270.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: Warning: a long semaphore wait:
--Thread 140161431643904 has waited at lock0lock.cc line 6837 for 270.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140161432647424 has waited at trx0trx.cc line 863 for 262.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 1
=====================================
2016-05-01 13:51:01 7f79e4b4b700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 68 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 11249 srv_active, 0 srv_shutdown, 208673 srv_idle
srv_master_thread log flush and writes: 219885
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 37569
--Thread 140161388840704 has waited at trx0rec.cc line 1295 for 0.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f7a246dadc0 created in file buf0buf.cc line 1069
a writer (thread id 140161388840704) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1056
Last time write locked in file /usr/local/src/mysql-5.6.27/storage/innobase/trx/trx0rec.cc line 1295
wait has ended
--Thread 140161446295296 has waited at lock0lock.cc line 6837 for 36.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140157129492224 has waited at trx0trx.cc line 193 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157119256320 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157121464064 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161369372416 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161394259712 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157125478144 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161371780864 has waited at trx0trx.cc line 1195 for 36.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161521604352 has waited at lock0wait.cc line 510 for 52.00 seconds the semaphore:
Mutex at 0x7f79ec4570c8 created file lock0lock.cc line 614, lock var 1
waiters flag 1
--Thread 140157123069696 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157119055616 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161397470976 has waited at lock0lock.cc line 5946 for 36.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140157121865472 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161375393536 has waited at trx0trx.cc line 863 for 43.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161380009728 has waited at lock0lock.cc line 6837 for 36.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161435457280 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157119457024 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161370375936 has waited at trx0trx.cc line 193 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157121664768 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161430038272 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161449305856 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161394861824 has waited at trx0trx.cc line 1195 for 37.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
InnoDB: ###### Diagnostic info printed to the standard error stream
--Thread 140157126481664 has waited at lock0lock.cc line 6837 for 37.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140157119657728 has waited at trx0sys.ic line 431 for 37.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157118453504 has waited at trx0trx.cc line 863 for 37.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157118854912 has waited at lock0lock.cc line 6837 for 37.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161388439296 has waited at trx0trx.cc line 2013 for 37.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161445693184 has waited at lock0lock.cc line 4416 for 37.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161441879808 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140157122066176 has waited at trx0trx.cc line 863 for 53.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161431643904 has waited at trx0trx.cc line 1195 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161426425600 has waited at lock0lock.cc line 6837 for 37.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161432848128 has waited at trx0trx.cc line 1195 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161379206912 has waited at trx0trx.cc line 1195 for 37.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161496426240 has waited at read0read.cc line 414 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161383220992 has waited at trx0rec.cc line 1457 for 49.00 seconds the semaphore:
S-lock on RW-latch at 0xd1d3278 created in file trx0purge.cc line 128
a writer (thread id 140161496426240) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file trx0rec.cc line 1457
Last time write locked in file /usr/local/src/mysql-5.6.27/storage/innobase/trx/trx0purge.cc line 1197
--Thread 140161374390016 has waited at lock0wait.cc line 95 for 36.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161381816064 has waited at lock0lock.cc line 6837 for 36.00 seconds the semaphore:
Mutex at 0x7f79ec457078 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 140161441478400 has waited at trx0rec.cc line 1457 for 56.00 seconds the semaphore:
S-lock on RW-latch at 0xd1d3278 created in file trx0purge.cc line 128
a writer (thread id 140161496426240) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file trx0rec.cc line 1457
Last time write locked in file /usr/local/src/mysql-5.6.27/storage/innobase/trx/trx0purge.cc line 1197
--Thread 140161432647424 has waited at trx0trx.cc line 863 for 56.00 seconds the semaphore:
Mutex at 0xd1c60f8 created file trx0sys.cc line 597, lock var 0
waiters flag 0
--Thread 140161529997056 has waited at log0log.cc line 2159 for 49.00 seconds the semaphore:
S-lock on RW-latch at 0xd1be058 created in file log0log.cc line 907
number of readers 0, waiters flag 0, lock_word: 100000
Last time read locked in file log0log.cc line 2159
Last time write locked in file /usr/local/src/mysql-5.6.27/storage/innobase/log/log0log.cc line 1944
OS WAIT ARRAY INFO: signal count 78027
Mutex spin waits 203541, rounds 135641, OS waits 1189
RW-shared spins 64274, rounds 1104435, OS waits 34133
RW-excl spins 38583, rounds 268488, OS waits 2065
Spin rounds per wait: 0.67 mutex, 17.18 RW-shared, 6.96 RW-excl
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: complete io for buf page (write thread) ev set
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (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: 1
116146 OS file reads, 287569 OS file writes, 176487 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.30 writes/s, 0.17 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 14, seg size 16, 20355 merges
merged operations:
 insert 23246, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 12749851, node heap has 3154 buffer(s)
527.29 hash searches/s, 35.50 non-hash searches/s
---
LOG
---
Log sequence number 12608071674
Log flushed up to   12608071674
Pages flushed up to 12608062434
Last checkpoint at  12608062035
0 pending log writes, 0 pending chkp writes
38319 log i/o's done, 0.03 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 6593445888; in additional pool allocated 0
Dictionary memory allocated 2835498
Buffer pool size   393212
Free buffers       262259
Database pages     127799
Old database pages 47258
Modified db pages  15
Pending reads 0
Pending writes: LRU 0, flush list 3, single page 0
Pages made young 36, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 124071, created 3728, written 229860
0.00 reads/s, 0.00 creates/s, 0.27 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 127799, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   49152
Free buffers       32497
Database pages     16268
Old database pages 6020
Modified db pages  4
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15847, created 421, written 37802
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 16268, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   49151
Free buffers       32784
Database pages     15965
Old database pages 5913
Modified db pages  2
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15489, created 476, written 26109
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 15965, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   49152
Free buffers       33272
Database pages     15486
Old database pages 5736
Modified db pages  1
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15161, created 325, written 23667
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 15486, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   49151
Free buffers       32607
Database pages     16140
Old database pages 5975
Modified db pages  2
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15684, created 456, written 31295
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 16140, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   49152
Free buffers       32504
Database pages     16250
Old database pages 6002
Modified db pages  1
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 8, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15740, created 510, written 32564
0.00 reads/s, 0.00 creates/s, 0.05 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 16250, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   49151
Free buffers       32925
Database pages     15839
Old database pages 5847
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15239, created 600, written 27844
0.00 reads/s, 0.00 creates/s, 0.10 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 15839, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   49152
Free buffers       33046
Database pages     15718
Old database pages 5790
Modified db pages  2
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 5, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15179, created 539, written 24954
0.00 reads/s, 0.00 creates/s, 0.08 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 15718, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   49151
Free buffers       32624
Database pages     16133
Old database pages 5975
Modified db pages  3
Pending reads 0
Pending writes: LRU 0, flush list 3, single page 0
Pages made young 4, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15732, created 401, written 25625
0.00 reads/s, 0.00 creates/s, 0.05 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 16133, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
61 read views open inside InnoDB
Main thread process no. 17977, id 140161529997056, state: making checkpoint
Number of rows inserted 147712, updated 47959, deleted 89012, read 2163996308
0.03 inserts/s, 0.00 updates/s, 0.00 deletes/s, 2529.48 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

从上面日志能分析,原来linux内核信号量默认设置太小,并发高的时候,造成大量等待, 
默认 
# cat /proc/sys/kernel/sem 
250     32000   32      128 

信号量:

当前系统信号量限制:

# ipcs -ls

—— Semaphore Limits ——–
max number of arrays = 128
max semaphores per array = 250
max semaphores system wide = 32000
max ops per semop call = 100

SEMMSL

  • 含义:每个信号量set中信号量最大个数

  • 设置:最小250;对于processes参数设置较大的系统建议设置为processes+10

SEMMNI

  • 含义:linux系统信号量set最大个数

  • 设置:最少128

SEMMNS

  • 含义:linux系统中信号量最大个数

  • 设置:至少32000;SEMMSL * SEMMNI

SEMOPM

  • 含义:semop系统调用允许的信号量最大个数

  • 设置:至少100;或者等于SEMMSL

查看信号量设置:cat /proc/sys/kernel/sem

order:SEMMSL, SEMMNS, SEMOPM, SEMMNI

# cat /proc/sys/kernel/sem
250    32000    100    128

修改:

sysctl -w kernel.sem="250 32000 100 128"
echo "kernel.sem=250 32000 100 128">> /etc/sysctl.conf


手动改变了信号量大小可以初步解决问题!我再仔细分析了一下日志:其中一段如下:

OS WAIT ARRAY INFO: signal count 78027
Mutex spin waits 203541, rounds 135641, OS waits 1189
RW-shared spins 64274, rounds 1104435, OS waits 34133
RW-excl spins 38583, rounds 268488, OS waits 2065
Spin rounds per wait: 0.67 mutex, 17.18 RW-shared, 6.96 RW-excl
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING


发现spin waits和OS waits等待时间相当高,在手册里查到了这一句话:

You can monitor the use of the adaptive hash index and the contention for its use in the SEMAPHORES section of the output of the SHOW ENGINE INNODB STATUS command. If you see many threads waiting on an RW-latch created in btr0sea.c, then it might be useful to disable adaptive hash indexing.


Sometimes, the read/write lock that guards access to the adaptive hash index can become a source of contention under heavy workloads, such as multiple concurrent joins.


由于自适应哈希索引造成大量的锁争用,进而堵塞很多进程,最终导致MySQL崩溃重启

找到原因后,关闭了自适应哈希索引,观察了一天后(参考性能图1月1日),spin waits和OS waits等待时间逐渐减少。

set global innodb_adaptive_hash_index = 0;


这样问题就能够得到解决了!