1

I have a sporadic deadlocking issue with MySQL 5.6. This server is configured as a read only slave, which is why it is extremely odd there is a deadlock issue.

I have innodb_lock_wait_timeout set to 120.

A subset (due to character limits on serverfault) of the output of SHOW ENGINE INNODB STATUS; is below.

I am hoping someone can point me in the right direction. What is the cause of this problem and how do I go about resolving it?

Update 4/12: I noticed the particularly peculiar issue is thread # 140123720021760 seems to be blocking itself.

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 29739376
--Thread 140123720021760 has waited at btr0sea.cc line 658 for 442.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x46a65388 created in file btr0sea.cc line 173
a writer (thread id 140123720021760) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 907
Last time write locked in file /export/home/pb2/build/sb_0-24964924-1505319557.6/rpm/BUILD/mysql-5.6.38/mysql-5.6.38/storage/innobase/btr/btr0sea.cc line 658
--Thread 140124318373632 has waited at btr0cur.cc line 2045 for 440.00 seconds the semaphore:
X-lock on RW-latch at 0x46a65388 created in file btr0sea.cc line 173
a writer (thread id 140123720021760) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 907
Last time write locked in file /export/home/pb2/build/sb_0-24964924-1505319557.6/rpm/BUILD/mysql-5.6.38/mysql-5.6.38/storage/innobase/btr/btr0sea.cc line 658
--Thread 140121070274304 has waited at row0sel.cc line 4074 for 439.00 seconds the semaphore:
S-lock on RW-latch at 0x46a65388 created in file btr0sea.cc line 173
a writer (thread id 140123720021760) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 907
Last time write locked in file /export/home/pb2/build/sb_0-24964924-1505319557.6/rpm/BUILD/mysql-5.6.38/mysql-5.6.38/storage/innobase/btr/btr0sea.cc line 658
------------
TRANSACTIONS
------------
Trx id counter 2444027091
Purge done for trx's n:o < 2444026968 undo n:o < 0 state: running but idle
History list length 1589
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 148840, OS thread handle 0x7f712cd85700, query id 215116859 192.168.100.50 play init
SHOW ENGINE INNODB STATUS
---TRANSACTION 0, not started
MySQL thread id 148839, OS thread handle 0x7f7078db9700, query id 215116452 192.168.100.50 play
---TRANSACTION 2444027012, ACTIVE 440 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 2, OS thread handle 0x7f713c389700, query id 215115280 System lock
---TRANSACTION 2444027088, ACTIVE 3 sec starting index read
mysql tables in use 10, locked 0
MySQL thread id 148862, OS thread handle 0x7f7109108700, query id 215116832 10.10.10.80 play_readonly statistics
select client0_.client_id as client_i1_33_0_, client0_.active as active2_33_0_, client0_.address_city as address_3_33_0_, client0_.address_country as address_4_33_0_, client0_.address_line1 as address_5_33_0_, client0_.address_line2 as address_6_33_0_, client0_.address_state as address_7_33_0_, client0_.address_zipcode as address_8_33_0_, client0_.bank_info as bank_inf9_33_0_, client0_.calendar_type as calenda10_33_0_, client0_.card_type_enabled_set as card_ty11_33_0_, client0_.catch_all_receipt_text as catch_a12_33_0_, client0_.city_of_incorporation as city_of13_33_0_, client0_.client_display
Trx read view will not see trx with id >= 2444027089, sees < 2444027012
--------
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
36630825 OS file reads, 231356872 OS file writes, 108178779 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 1, free list len 70724, seg size 70726, 4826685 merges
merged operations:
 insert 6743692, delete mark 49985569, delete 2426777
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 84999163, node heap has 341459 buffer(s)
0.00 hash searches/s, 4.50 non-hash searches/s
---
LOG
---
Log sequence number 2131849036943
Log flushed up to   2131849036943
Pages flushed up to 2131849036943
Last checkpoint at  2131849036943
0 pending log writes, 0 pending chkp writes
37238698 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 43956305920; in additional pool allocated 0
Dictionary memory allocated 2406027
Buffer pool size   2621440
Free buffers       8193
Database pages     2271787
Old database pages 838446
Modified db pages  0
Pending reads 0
Pending writes: LRU 1, flush list 0, single page 0
Pages made young 288176007, not young 1989790258
0.10 youngs/s, 0.00 non-youngs/s
Pages read 36629170, created 1207472, written 164204069
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 11 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2271787, unzip_LRU len: 0
I/O sum[24]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   327680
Free buffers       1025
Database pages     283983
Old database pages 104809
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 40220727, not young 283474530
0.00 youngs/s, 0.00 non-youngs/s
Pages read 5186114, created 152096, written 35871221
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: 283983, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   327680
Free buffers       1026
Database pages     283990
Old database pages 104812
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 36212975, not young 249869675
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4641916, created 151079, written 14821449
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: 283990, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   327680
Free buffers       1025
Database pages     283923
Old database pages 104787
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 31148941, not young 207780893
0.10 youngs/s, 0.00 non-youngs/s
Pages read 3912247, created 147944, written 19145924
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 58 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 283923, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   327680
Free buffers       1025
Database pages     283971
Old database pages 104805
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 36726178, not young 253275164
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4671182, created 151023, written 25773402
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: 283971, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   327680
Free buffers       1022
Database pages     283999
Old database pages 104815
Modified db pages  0
Pending reads 0
Pending writes: LRU 1, flush list 0, single page 0
Pages made young 36790229, not young 268599143
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4620148, created 151929, written 20173631
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: 283999, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   327680
Free buffers       1025
Database pages     284004
Old database pages 104817
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 33417599, not young 219971495
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4074681, created 146202, written 17018304
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: 284004, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   327680
Free buffers       1021
Database pages     283942
Old database pages 104795
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 36990403, not young 256117529
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4774761, created 152747, written 16831520
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: 283942, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   327680
Free buffers       1024
Database pages     283975
Old database pages 104806
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 36668955, not young 250701829
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4748121, created 154452, written 14568618
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: 283975, unzip_LRU len: 0
I/O sum[3]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
78 read views open inside InnoDB
Main thread process no. 2221, id 140124339353344, state: sleeping
Number of rows inserted 126495327, updated 53443514, deleted 99690029, read 137185949856
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 2.30 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
jnrcorp
  • 125
  • 5

1 Answers1

0

Even SELECT statements can cause locking activity. To minimize the impact of this you can set the transaction isolation level to READ UNCOMMITTED before you execute your SELECT statements. Note that you might potentially see data that isn't yet committed by a transaction.

nutcase
  • 80
  • 7
  • Thank you for this information. Can you please reference MySQL innodb documentation that states this? I cannot find it. – jnrcorp Apr 12 '18 at 15:32
  • Start here: https://dev.mysql.com/doc/refman/5.7/en/innodb-transaction-isolation-levels.html. Basically what you are trading is concurrency vs. consistency. If you are certain that your app is only reading committed transactions from the R/O slave then changing the concurrency level shouldn't give you any difficulties. – nutcase Apr 13 '18 at 16:17