MySQL – Debugging Lock Timeout with SHOW ENGINE INNODB STATUS

deadlockMySQL

I am keeping getting this lock wait time out. Below is my current settings.

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

innodb_file_per_table
innodb_lock_wait_timeout=120
innodb_buffer_pool=8G
innodb_log_file_size=512M

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

I think on buffer pool and log file is sufficient. In fact I am doing some very basic testing with very little data and keep getting lock wait time out exceeded error.
Below is my show innodb engine status. I have index on the where field but yet it get locked any other settings to be tweak ?

mysql> SHOW ENGINE INNODB STATUS\G;
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
151009  8:16:46 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 32 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 44793, signal count 35849
Mutex spin waits 0, rounds 862558, OS waits 29155
RW-shared spins 28241, OS waits 14120; RW-excl spins 459, OS waits 270
------------
TRANSACTIONS
------------
Trx id counter 0 482854
Purge done for trx's n:o < 0 482849 undo n:o < 0 0
History list length 12
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 3163, OS thread id 140716376987392
MySQL thread id 861249, query id 8416389 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION 0 482853, ACTIVE 40 sec, process no 3163, OS thread id 140716377253632 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 861231, query id 8416386 localhost 127.0.0.1 user11 Updating
UPDATE tblMD SET speed='000',course='240',dateTime='2015-10-09 05:13:10' WHERE MDSerialNumber='85112'
Trx read view will not see trx with id >= 0 482854, sees < 0 482849
------- TRX HAS BEEN WAITING 40 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 16 page no 4 n bits 80 index `MDSerialNumber` of table `db1`.`tblMD` trx id 0 482853 lock_mode X waiting
Record lock, heap no 11 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 8; hex 4143303033393835; asc 85112;; 1: len 4; hex 8000000a; asc     ;;

------------------
---TRANSACTION 0 482852, ACTIVE 101 sec, process no 3163, OS thread id 140716371396352 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 861230, query id 8416368 localhost 127.0.0.1 user11 Updating
UPDATE tblMD SET speed='000',course='240',dateTime='2015-10-09 05:08:09' WHERE MDSerialNumber='85112'
Trx read view will not see trx with id >= 0 482853, sees < 0 482849
------- TRX HAS BEEN WAITING 101 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 16 page no 4 n bits 80 index `MDSerialNumber` of table `db1`.`tblMD` trx id 0 482852 lock_mode X waiting
Record lock, heap no 11 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 8; hex 4143303033393835; asc 85112;; 1: len 4; hex 8000000a; asc     ;;

------------------
---TRANSACTION 0 482849, ACTIVE 384 sec, process no 3163, OS thread id 140716379383552
14 lock struct(s), heap size 3024, 10 row lock(s), undo log entries 8
MySQL thread id 861229, query id 8416328 localhost 127.0.0.1 user11
Trx read view will not see trx with id >= 0 482850, sees < 0 482850
--------
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 (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
0 OS file reads, 167042 OS file writes, 103622 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 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 17700857, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 41870396
Log flushed up to   0 41870396
Last checkpoint at  0 41870396
0 pending log writes, 0 pending chkp writes
37745 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 9433142458; in additional pool allocated 977152
Dictionary memory allocated 160280
Buffer pool size   524288
Free buffers       523535
Database pages     751
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 0, created 1239, written 164979
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
4 read views open inside InnoDB
Main thread process no. 3163, id 140707062236928, state: waiting for server activity
Number of rows inserted 44586, updated 44101, deleted 0, read 44349183
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

ERROR:

Best Answer

Both UPDATEs are setting the same row, so something has to give.

Let's see the entire transaction (BEGIN...COMMIT).