MySQL Forums
Forum List  »  InnoDB

Lock wait timeout exceeded when redo log switch was happening.
Posted by: Ragavan Dinakar
Date: April 03, 2017 03:47AM

Hi,

We are getting Lock wait timeout exceeded from an SP inserting records not much less than 100 rows. I found that there was log rotation happened at the same time. Normally it takes few seconds to complete.

The as per the redo DB Log files the log switch started around 2017-04-02 20:32:05 it completed at 8:36:28 pm i.e., 4.5 minutes.
As per oracle it’s given to increase the innodb_lock_wait_timeout
The Innodb_lock_wait_timeout is 50 seconds can we increase to 300 seconds or it would create deadlocks if we increase the lock wait time.

Any help regarding this would be appreciated.

Thanks and Regards,
Ragavan

Please find below the InnoDB status:


=====================================
2017-04-03 17:08:14 7fa4ae0f8700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 18 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 382417 srv_active, 0 srv_shutdown, 23691238 srv_idle
srv_master_thread log flush and writes: 24073655
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1296567
OS WAIT ARRAY INFO: signal count 1136067
Mutex spin waits 632395354, rounds 660153926, OS waits 564984
RW-shared spins 550201, rounds 15208647, OS waits 498122
RW-excl spins 90633, rounds 7619287, OS waits 229457
Spin rounds per wait: 1.04 mutex, 27.64 RW-shared, 84.07 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-01-20 09:48:36 7fa4b40e2700
*** (1) TRANSACTION:
TRANSACTION 38038601, ACTIVE 2 sec fetching rows
mysql tables in use 8, locked 8
LOCK WAIT 167 lock struct(s), heap size 30248, 28855 row lock(s), undo log entries 147
MySQL thread id 185430, OS thread handle 0x7fa4ae1fc700, query id 132149093 192.168.1.121 DBA updating
Update so_packing_dtls set modify_status = 'Y'
where comp_code = new.comp_code and so_no = new.so_no
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 29659 page no 348 n bits 136 index `PRIMARY` of table `konverge_live`.`so_packing_dtls` trx id 38038601 lock_mode X waiting
Record lock, heap no 70 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 2; hex 3031; asc 01;;
1: len 15; hex 534f522d4b50313730343031323434; asc SOR-KP170401244;;
2: len 6; hex 000002446c4b; asc DlK;;
3: len 7; hex f200000286012c; asc ,;;
4: len 1; hex 4e; asc N;;
5: len 1; hex 4e; asc N;;
6: len 4; hex 73746f31; asc sto1;;
7: len 5; hex 999ba89c23; asc #;;
8: len 4; hex 73746f31; asc sto1;;
9: len 5; hex 999ba89c23; asc #;;
10: SQL NULL;
11: SQL NULL;
12: SQL NULL;
13: SQL NULL;

*** (2) TRANSACTION:
TRANSACTION 38038603, ACTIVE 1 sec starting index read
mysql tables in use 5, locked 5
19 lock struct(s), heap size 2936, 12 row lock(s), undo log entries 24
MySQL thread id 185419, OS thread handle 0x7fa4b40e2700, query id 132149315 192.168.1.122 DBA updating
update in_item set committed_qty = ifnull(committed_qty,0) + new.qty_order
where item_id = new.item_id and comp_code = new.comp_code
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 29659 page no 348 n bits 136 index `PRIMARY` of table `konverge_live`.`so_packing_dtls` trx id 38038603 lock_mode X locks rec but not gap
Record lock, heap no 70 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
0: len 2; hex 3031; asc 01;;
1: len 15; hex 534f522d4b50313730343031323434; asc SOR-KP170401244;;
2: len 6; hex 000002446c4b; asc DlK;;
3: len 7; hex f200000286012c; asc ,;;
4: len 1; hex 4e; asc N;;
5: len 1; hex 4e; asc N;;
6: len 4; hex 73746f31; asc sto1;;
7: len 5; hex 999ba89c23; asc #;;
8: len 4; hex 73746f31; asc sto1;;
9: len 5; hex 999ba89c23; asc #;;
10: SQL NULL;
11: SQL NULL;
12: SQL NULL;
13: SQL NULL;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 29541 page no 13 n bits 120 index `AK_KEY_1_IN_ITEM` of table `konverge_live`.`in_item` trx id 38038603 lock_mode X locks rec but not gap waiting
Record lock, heap no 21 PHYSICAL RECORD: n_fields 65; compact format; info bits 0
0: len 2; hex 3031; asc 01;;
1: len 14; hex 8000000000000000000170000000; asc p ;;
2: len 6; hex 000002446c49; asc DlI;;
3: len 7; hex 710000039a110f; asc q ;;
4: len 4; hex 36323230; asc 6220;;
5: len 7; hex 424549204d5520; asc BEI MU ;;
6: len 3; hex 4b5031; asc KP1;;
7: len 3; hex 424f54; asc BOT;;
8: len 4; hex 80000001; asc ;;
9: len 4; hex 80000001; asc ;;
10: len 4; hex 80000001; asc ;;
11: len 1; hex 4c; asc L;;
12: len 4; hex 80000000; asc ;;
13: SQL NULL;
14: SQL NULL;
15: SQL NULL;
16: len 9; hex 800000000000f30000; asc ;;
17: len 9; hex 800000000001400000; asc @ ;;
18: len 9; hex 800000000000ff0000; asc ;;
19: len 9; hex 800000000000000000; asc ;;
20: len 9; hex 80000000000a01468e; asc F ;;
21: len 9; hex 800000000000000000; asc ;;
22: len 9; hex 800000000c9a0b71b0; asc q ;;
23: SQL NULL;
24: SQL NULL;
25: SQL NULL;
26: SQL NULL;
27: len 5; hex 3136383932; asc 16892;;
28: len 9; hex 800000000000000000; asc ;;
29: len 13; hex 34373139383639333936333237; asc 4719869396327;;
30: len 6; hex e8b49de6af8d; asc ;;
31: len 4; hex 80000000; asc ;;
32: len 1; hex 46; asc F;;
33: len 4; hex 80000000; asc ;;
34: len 3; hex 424f54; asc BOT;;
35: len 9; hex 800000000001000000; asc ;;
36: len 9; hex 800000000000180000; asc ;;
37: len 9; hex 800000000000080000; asc ;;
38: len 3; hex 444241; asc DBA;;
39: len 5; hex 99977a0000; asc z ;;
40: len 3; hex 444241; asc DBA;;
41: len 5; hex 99977a0000; asc z ;;
42: SQL NULL;
43: len 4; hex 80000000; asc ;;
44: len 4; hex 80000000; asc ;;
45: len 9; hex 800000000000320000; asc 2 ;;
46: SQL NULL;
47: SQL NULL;
48: SQL NULL;
49: SQL NULL;
50: SQL NULL;
51: SQL NULL;
52: len 1; hex 4e; asc N;;
53: SQL NULL;
54: len 4; hex 80000000; asc ;;
55: len 1; hex 4e; asc N;;
56: len 3; hex 424f54; asc BOT;;
57: len 9; hex 800000000001000000; asc ;;
58: SQL NULL;
59: SQL NULL;
60: SQL NULL;
61: len 1; hex 31; asc 1;;
62: len 1; hex 4e; asc N;;
63: len 6; hex 362e33333a31; asc 6.33:1;;
64: len 17; hex 46726974696c6c6172696120285a686529; asc Fritillaria (Zhe);;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 41152216
Purge done for trx's n:o < 41152216 undo n:o < 0 state: running but idle
History list length 839
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 251681, OS thread handle 0x7fa4ae0f8700, query id 177820414 219.75.38.48 DBA init
SHOW ENGINE INNODB STATUS
---TRANSACTION 0, not started
MySQL thread id 251680, OS thread handle 0x7fa4b40a1700, query id 177820280 219.75.38.48 DBA cleaning up
---TRANSACTION 0, not started
MySQL thread id 251537, OS thread handle 0x7fa4b6c5f700, query id 177820247 219.75.38.48 DBA cleaning up
--------
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
391854 OS file reads, 9968125 OS file writes, 6706195 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 1001, seg size 1003, 2088 merges
merged operations:
insert 716, delete mark 895724, delete 2718
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 4730647, node heap has 2838 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 45220641578
Log flushed up to 45220641578
Pages flushed up to 45220641578
Last checkpoint at 45220641578
0 pending log writes, 0 pending chkp writes
2565784 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 2197815296; in additional pool allocated 0
Dictionary memory allocated 3936413
Buffer pool size 131064
Free buffers 8193
Database pages 120033
Old database pages 44145
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 15778713, not young 11624410
0.00 youngs/s, 0.00 non-youngs/s
Pages read 390529, created 1292910, written 5384521
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, Random read ahead 0.00/s
LRU len: 120033, 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 16383
Free buffers 1024
Database pages 15007
Old database pages 5519
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1962166, not young 1480111
0.00 youngs/s, 0.00 non-youngs/s
Pages read 45753, created 161349, written 745078
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, Random read ahead 0.00/s
LRU len: 15007, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 16383
Free buffers 1024
Database pages 15007
Old database pages 5519
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1642850, not young 1056231
0.00 youngs/s, 0.00 non-youngs/s
Pages read 38769, created 161509, written 399239
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, Random read ahead 0.00/s
LRU len: 15007, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size 16383
Free buffers 1024
Database pages 15000
Old database pages 5517
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1826519, not young 1186344
0.00 youngs/s, 0.00 non-youngs/s
Pages read 39264, created 163324, written 693152
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, Random read ahead 0.00/s
LRU len: 15000, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size 16383
Free buffers 1024
Database pages 15000
Old database pages 5517
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2012163, not young 1147301
0.00 youngs/s, 0.00 non-youngs/s
Pages read 40698, created 162408, written 781880
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, Random read ahead 0.00/s
LRU len: 15000, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size 16383
Free buffers 1025
Database pages 15002
Old database pages 5517
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2395183, not young 2018582
0.00 youngs/s, 0.00 non-youngs/s
Pages read 61215, created 160925, written 817040
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, Random read ahead 0.00/s
LRU len: 15002, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size 16383
Free buffers 1024
Database pages 15000
Old database pages 5517
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2155366, not young 1536959
0.00 youngs/s, 0.00 non-youngs/s
Pages read 56717, created 161017, written 622402
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, Random read ahead 0.00/s
LRU len: 15000, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size 16383
Free buffers 1024
Database pages 15007
Old database pages 5519
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1741645, not young 1346268
0.00 youngs/s, 0.00 non-youngs/s
Pages read 49201, created 160723, written 670017
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, Random read ahead 0.00/s
LRU len: 15007, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size 16383
Free buffers 1024
Database pages 15010
Old database pages 5520
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2042821, not young 1852614
0.00 youngs/s, 0.00 non-youngs/s
Pages read 58912, created 161655, written 655713
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, Random read ahead 0.00/s
LRU len: 15010, 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
0 read views open inside InnoDB
Main thread process no. 2487, id 140345394501376, state: sleeping
Number of rows inserted 61172573, updated 12435920, deleted 7526868, read 271264177267
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Options: ReplyQuote


Subject
Views
Written By
Posted
Lock wait timeout exceeded when redo log switch was happening.
192
April 03, 2017 03:47AM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.