All of the sudden mysql became unresponsive we are not sure of the reason, when we check mysql error log we find following, but for us it is hard to interpret it, can anybody help to understand it and what problem it is reflecting.
InnoDB: Warning: a long semaphore wait:
--Thread 140367614420736 has waited at buf0buf.cc line 2576 for 245.00 seconds the semaphore:
S-lock on RW-latch at 0x7fafecceea40 created in file buf0buf.cc line 1069
a writer (thread id 140367693993728) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /build/mysql-5.6-54V6wZ/mysql-5.6-5.6.27/storage/innobase/buf/buf0buf.cc line 3691
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
=====================================
2016-04-20 05:14:00 7fa9e709e700InnoDB: ###### Diagnostic info printed to the standard error stream
INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 60 seconds
-----------------
BACKGROUND THREAD
-----------------
InnoDB: Warning: a long semaphore wait:
srv_master_thread loops: 600927 srv_active, 0 srv_shutdown, 1532 srv_idle
srv_master_thread log flush and writes: 602454
--Thread 140367614420736 has waited at buf0buf.cc line 2576 for 292.00 seconds the semaphore:
----------
SEMAPHORES
----------
2016-04-20 05:14:10 13884 [ERROR] Slave I/O: error connecting to master 'saas@10.147.3.249:3306' - retry-time: 60 retries: 3230, Error_code: 2003
S-lock on RW-latch at 0x7fafecceea40 created in file buf0buf.cc line 1069
a writer (thread id 140367693993728) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /build/mysql-5.6-54V6wZ/mysql-5.6-5.6.27/storage/innobase/buf/buf0buf.cc line 3691
OS WAIT ARRAY INFO: reservation count 2131394
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
--Thread 140367603181312 has waited at dict0dict.cc line 1122 for 81.00 seconds the semaphore:
InnoDB: Pending preads 0, pwrites 0
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367585920768 has waited at dict0dict.cc line 1122 for 91.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367601776384 has waited at dict0dict.cc line 1122 for 98.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367593346816 has waited at dict0dict.cc line 1122 for 102.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367613818624 has waited at dict0dict.cc line 1122 for 111.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
InnoDB: ###### Diagnostic info printed to the standard error stream
--Thread 140367786313472 has waited at btr0cur.cc line 256 for 81.00 seconds the semaphore:
X-lock on RW-latch at 0x7faa235e4440 created in file buf0buf.cc line 1069
number of readers 0, waiters flag 0, lock_word: 100000
Last time read locked in file btr0cur.cc line 256
Last time write locked in file /build/mysql-5.6-54V6wZ/mysql-5.6-5.6.27/storage/innobase/btr/btr0cur.cc line 256
--Thread 140367592744704 has waited at ha_innodb.cc line 4454 for 129.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367594149632 has waited at dict0dict.cc line 1122 for 130.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367612815104 has waited at dict0dict.cc line 1122 for 133.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140366980114176 has waited at ha_innodb.cc line 4454 for 138.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367622850304 has waited at ha_innodb.cc line 4454 for 144.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367595955968 has waited at dict0dict.cc line 1122 for 146.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367614420736 has waited at buf0buf.cc line 2576 for 378.00 seconds the semaphore:
S-lock on RW-latch at 0x7fafecceea40 created in file buf0buf.cc line 1069
a writer (thread id 140367693993728) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file /build/mysql-5.6-54V6wZ/mysql-5.6-5.6.27/storage/innobase/buf/buf0buf.cc line 3691
--Thread 140367685601024 has waited at dict0dict.cc line 967 for 160.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140366978909952 has waited at ha_innodb.cc line 4454 for 167.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367609603840 has waited at ha_innodb.cc line 4454 for 170.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367612212992 has waited at ha_innodb.cc line 4454 for 166.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140366975297280 has waited at dict0dict.cc line 1122 for 152.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367619438336 has waited at dict0dict.cc line 1122 for 156.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367626262272 has waited at dict0dict.cc line 560 for 157.00 seconds the semaphore:
Mutex at 0x7fb5fde948a8 created file dict0dict.cc line 1057, lock var 1
waiters flag 1
--Thread 140367693993728 has waited at btr0cur.cc line 256 for 135.00 seconds the semaphore:
S-lock on RW-latch at 0x7faa235e4440 created in file buf0buf.cc line 1069
number of readers 0, waiters flag 0, lock_word: 100000
Last time read locked in file btr0cur.cc line 256
Last time write locked in file /build/mysql-5.6-54V6wZ/mysql-5.6-5.6.27/storage/innobase/btr/btr0cur.cc line 256
OS WAIT ARRAY INFO: signal count 311377651
Mutex spin waits 381749010, rounds 444901271, OS waits 1111790
RW-shared spins 60068449, rounds 98796869, OS waits 538751
RW-excl spins 5767435, rounds 396478923, OS waits 341484
Spin rounds per wait: 1.17 mutex, 1.64 RW-shared, 68.74 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-04-19 14:52:39 7fa9e0281700
*** (1) TRANSACTION:
TRANSACTION 10827263428, ACTIVE 2 sec starting index read
mysql tables in use 10, locked 10
LOCK WAIT 1079 lock struct(s), heap size 144936, 65860 row lock(s), undo log entries 5
MySQL thread id 9267974, OS thread handle 0x7fa9e27d4700, query id 2939061492 ip-10-0-0-105.ec2.internal 10.0.0.105 saas Sending data
UPDATE fdtraninfo AS fdtraninfo,fdrentalinfo AS fdrentalinfo SET fdtraninfo.statusunkid=3 , fdrentalinfo.statusunkid= 3 WHERE fdtraninfo.tranunkid=fdrentalinfo.tranunkid AND fdrentalinfo.statusunkid=9 AND fdrentalinfo.hotel_code='153' AND fdrentalinfo.rentaldate='2016-04-19'
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 69202 page no 3622 n bits 584 index `idx_fdrentalinfo_test` of table `saas_20120316`.`fdrentalinfo` trx id 10827263428 lock_mode X waiting
Record lock, heap no 503 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 803822042b7393ab; asc 8" +s ;;
1: len 4; hex 80000009; asc ;;
2: len 8; hex 803822042b73e524; asc 8" +s $;;
*** (2) TRANSACTION:
TRANSACTION 10827263451, ACTIVE 2 sec starting index read, thread declared inside InnoDB 5000
mysql tables in use 9, locked 9
4506 lock struct(s), heap size 439848, 466906 row lock(s), undo log entries 17
MySQL thread id 9267935, OS thread handle 0x7fa9e0281700, query id 2939078654 ip-10-0-0-105.ec2.internal 10.0.0.105 saas updating
UPDATE fdtraninfo SET roomtypeunkid= NAME_CONST('pRoomTypeUnkId',15800000000000002) WHERE tranunkid= NAME_CONST('pTranUnkId',15800000000005035)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 69202 page no 3622 n bits 584 index `idx_fdrentalinfo_test` of table `saas_20120316`.`fdrentalinfo` trx id 10827263451 lock_mode X
Record lock, heap no 503 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 803822042b7393ab; asc 8" +s ;;
1: len 4; hex 80000009; asc ;;
2: len 8; hex 803822042b73e524; asc 8" +s $;;
Record lock, heap no 504 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 803822042b7393ab; asc 8" +s ;;
1: len 4; hex 80000004; asc ;;
2: len 8; hex 803822042b73e522; asc 8" +s ";;
Record lock, heap no 505 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 803822042b7393ab; asc 8" +s ;;
1: len 4; hex 80000004; asc ;;
2: len 8; hex 803822042b73e523; asc 8" +s #;;
Record lock, heap no 510 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 803822042b7393ac; asc 8" +s ;;
1: len 4; hex 80000004; asc ;;
2: len 8; hex 803822042b73e525; asc 8" +s %;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 103678 page no 794 n bits 160 index `PRIMARY` of table `saas_20120316`.`fdtraninfo` trx id 10827263451 lock_mode X locks rec but not gap waiting
Record lock, heap no 45 PHYSICAL RECORD: n_fields 78; compact format; info bits 0
0: len 8; hex 803822042b7393ab; asc 8" +s ;;
1: len 6; hex 0002854c69d9; asc Li ;;
2: len 7; hex 51000200340b6b; asc Q 4 k;;
3: len 4; hex 8000009e; asc ;;
4: len 4; hex 800007e0; asc ;;
5: len 5; hex 999926802d; asc & -;;
6: len 5; hex 9999c43000; asc 0 ;;
7: len 5; hex 9999c8b780; asc ;;
8: SQL NULL;
9: SQL NULL;
10: SQL NULL;
11: SQL NULL;
12: SQL NULL;
13: SQL NULL;
14: SQL NULL;
15: SQL NULL;
16: len 1; hex 80; asc ;;
17: SQL NULL;
18: SQL NULL;
19: len 4; hex 80000004; asc ;;
20: SQL NULL;
21: SQL NULL;
22: SQL NULL;
23: len 8; hex 8000000000025018; asc P ;;
24: SQL NULL;
25: SQL NULL;
26: SQL NULL;
27: SQL NULL;
28: SQL NULL;
29: SQL NULL;
30: SQL NULL;
31: len 4; hex 34353733; asc 4573;;
32: SQL NULL;
33: SQL NULL;
34: SQL NULL;
35: SQL NULL;
36: len 8; hex 803822042b739407; asc 8" +s ;;
37: len 8; hex 803822042b7393ab; asc 8" +s ;;
38: SQL NULL;
39: len 8; hex 803822042b738001; asc 8" +s ;;
40: SQL NULL;
41: SQL NULL;
42: SQL NULL;
43: len 1; hex 80; asc ;;
44: SQL NULL;
45: len 0; hex ; asc ;;
46: SQL NULL;
47: len 8; hex 803822042b738001; asc 8" +s ;;
48: len 8; hex 803822042b738001; asc 8" +s ;;
49: SQL NULL;
50: SQL NULL;
51: len 8; hex 803822042b738002; asc 8" +s ;;
52: len 1; hex 81; asc ;;
53: len 1; hex 80; asc ;;
54: len 1; hex 81; asc ;;
55: len 1; hex 80; asc ;;
56: SQL NULL;
57: len 4; hex 34303836; asc 4086;;
58: len 2; hex 656e; asc en;;
59: len 7; hex 4445534b544f50; asc DESKTOP;;
60: SQL NULL;
61: SQL NULL;
62: SQL NULL;
63: SQL NULL;
64: SQL NULL;
65: SQL NULL;
66: SQL NULL;
67: len 1; hex 82; asc ;;
68: SQL NULL;
69: SQL NULL;
70: len 8; hex 8000000000000000; asc ;;
71: SQL NULL;
72: SQL NULL;
73: SQL NULL;
74: SQL NULL;
75: len 1; hex 80; asc ;;
76: len 1; hex 81; asc ;;
77: len 0; hex ; asc ;;
*** WE ROLL BACK TRANSACTION (1)
--------
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: complete io for buf page (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: complete io for buf page (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: complete io for buf page (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 6 [6, 0, 0, 0] , aio writes: 18 [13, 0, 5, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
2209562 OS file reads, 10418810 OS file writes, 7474343 OS fsyncs
0.00 reads/s, 16384 avg bytes/read, 1.47 writes/s, 0.23 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 3, free list len 83911, seg size 83915, 24926 merges
merged operations:
insert 84511, delete mark 1433863, delete 59194
discarded operations:
insert 0, delete mark 4, delete 0
Hash table size 95623823, node heap has 110053 buffer(s)
222.11 hash searches/s, 62.13 non-hash searches/s
---
LOG
---
Log sequence number 635352902939
Log flushed up to 635352631347
Pages flushed up to 635348739144
Last checkpoint at 635333157573
0 pending log writes, 0 pending chkp writes
3427391 log i/o's done, 0.01 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 49450844160; in additional pool allocated 0
Dictionary memory allocated 45979819
Buffer pool size 2949112
Free buffers 600760
Database pages 2238299
Old database pages 826400
Modified db pages 232
Pending reads 1
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 5687, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2157895, created 80403, written 5680416
0.08 reads/s, 0.00 creates/s, 1.54 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: 2238299, unzip_LRU len: 0
I/O sum[0]:cur[3200], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 368639
Free buffers 75763
Database pages 279141
Old database pages 103061
Modified db pages 12
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 607, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 269417, created 9724, written 1225582
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: 279141, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 368639
Free buffers 71747
Database pages 283096
Old database pages 104521
Modified db pages 20
Pending reads 0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 775, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 272612, created 10484, written 678841
0.01 reads/s, 0.00 creates/s, 0.29 writes/s
Buffer pool hit rate 999 / 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: 283096, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 368639
Free buffers 74110
Database pages 280858
Old database pages 103695
Modified db pages 18
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 677, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 270777, created 10081, written 422117
0.00 reads/s, 0.00 creates/s, 0.23 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: 280858, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 368639
Free buffers 73916
Database pages 280936
Old database pages 103724
Modified db pages 49
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 714, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 269752, created 11184, written 703005
0.02 reads/s, 0.00 creates/s, 0.38 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: 280936, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 368639
Free buffers 73212
Database pages 281673
Old database pages 103996
Modified db pages 56
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 735, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 271422, created 10251, written 513175
0.02 reads/s, 0.00 creates/s, 0.11 writes/s
Buffer pool hit rate 999 / 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: 281673, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 368639
Free buffers 78191
Database pages 276638
Old database pages 102138
Modified db pages 17
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 699, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 267647, created 8990, written 444052
0.01 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: 276638, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 368639
Free buffers 79338
Database pages 275551
Old database pages 101736
Modified db pages 13
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 733, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 266250, created 9301, written 802432
0.00 reads/s, 0.00 creates/s, 0.09 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: 275551, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 368639
Free buffers 74483
Database pages 280406
Old database pages 103529
Modified db pages 47
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 747, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 270018, created 10388, written 891212
0.01 reads/s, 0.00 creates/s, 0.25 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: 280406, unzip_LRU len: 0
I/O sum[0]:cur[400], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
5 queries inside InnoDB, 0 queries in queue
62 read views open inside InnoDB
Main thread process no. 13884, id 140367693993728, state: sleeping
Number of rows inserted 3798574, updated 3943210, deleted 1319394, read 1045959061796
0.00 inserts/s, 0.02 updates/s, 1.00 deletes/s, 872.50 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
