Lock wait timeout exceeded; Try restarting transaction

Al ejecutar una query en un MySQL contra una tabla con el engine InnoDB nos podemos encontrar con el error:

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

La variable innodb_lock_wait_timeout permite definir el tiempo va a esperar una query a obterner un lock, por lo que podemos minimizar este error aumentando este timeout a costa de asumir que las queries pueden tener esta tiempo el thread bloqueado a la espera. Dependiendo del entorno quizá nos interesa incluso bajarlo para evitar que las queries se queden esperando (por ejemplo en entorno web). Vamos a ver como investigar este problema viendo las transacciones implicadas en un problema de este tipo.

Primero vamos a ver como ver las transacciones de InnoDB. Para ello primero vamos a desactivar el AUTOCOMMIT y dejar un INSERT pendiente en una tabla:

sess1> create table systemadmin(id int, valor int) engine=innodb;
Query OK, 0 rows affected (0.00 sec)

sess1> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

sess1> insert into systemadmin values (1,2);
Query OK, 1 row affected (0.00 sec)

En otra sesión podemos ver como en la tabla aún no esta el registro porque aún no hemos hecho el COMMIT:

sess2> select * from systemadmin;
Empty set (0.00 sec)

Para ver el bloqueo deberemos hacer un SHOW INNODB STATUS:

sess2> show innodb status;
(...)
=====================================
111220 13:58:27 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 19 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 275631, signal count 201762
Mutex spin waits 0, rounds 5188747, OS waits 11664
RW-shared spins 523201, OS waits 247659; RW-excl spins 45648, OS waits 14109
------------
TRANSACTIONS
------------
Trx id counter 3 1138852222
Purge done for trx's n:o < 3 1138852213 undo n:o < 0 0
History list length 1204
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 3 1138852221, not started, process no 12825, OS thread id 1173952832
MySQL thread id 30099, query id 830459 127.0.0.1 root
show innodb status
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1204304192
MySQL thread id 29207, query id 827945 172.25.12.22 whatthefrak
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1215752512
MySQL thread id 29132, query id 811974 172.25.10.101 whatthefrak
---TRANSACTION 3 1138852220, ACTIVE 14 sec, process no 12825, OS thread id 1174751552
1 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 29991, query id 830457 127.0.0.1 root
--------
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
3178681 OS file reads, 71846 OS file writes, 40351 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.47 writes/s, 0.26 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5579, seg size 5581,
2186 inserts, 2186 merged recs, 206 merges
Hash table size 276707, node heap has 188 buffer(s)
0.00 hash searches/s, 0.05 non-hash searches/s
---
LOG
---
Log sequence number 1008 1723205347
Log flushed up to   1008 1723205347
Last checkpoint at  1008 1723205347
0 pending log writes, 0 pending chkp writes
30247 log i/o's done, 0.11 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 180001002; in additional pool allocated 1048576
Dictionary memory allocated 12285888
Buffer pool size   8192
Free buffers       0
Database pages     8004
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 6463337, created 37105, written 132411
0.00 reads/s, 0.05 creates/s, 0.32 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 12825, id 1172621632, state: sleeping
Number of rows inserted 2864154, updated 203150, deleted 1649, read 1145452124
0.05 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
 |
(...)
1 row in set, 1 warning (0.00 sec)

En la parte de transacciones podremos ver como existe un bloqueo para el thread id (29991) de la sessión 1 correspondiente a los datos pendientes del COMMIT:

---TRANSACTION 3 1138852220, ACTIVE 14 sec, process no 12825, OS thread id 1174751552
1 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 29991, query id 830457 127.0.0.1 root

En el momento que hagamos el COMMIT desaparecerá:

sess1> commit;
Query OK, 0 rows affected (0.00 sec)

En TRANSACTIONS de SHOW INNODB STATUS veremos:

------------
TRANSACTIONS
------------
Trx id counter 3 1138852234
Purge done for trx's n:o < 3 1138852225 undo n:o < 0 0
History list length 1206
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 3 1138852221, not started, process no 12825, OS thread id 1173952832
MySQL thread id 30099, query id 830528 127.0.0.1 root
show innodb status
---TRANSACTION 3 1138852220, not started, process no 12825, OS thread id 1174751552
MySQL thread id 29991, query id 830502 127.0.0.1 root
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1204304192
MySQL thread id 29207, query id 827945 172.25.12.22 whatthefrak
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1215752512
MySQL thread id 29132, query id 811974 172.25.10.101 whatthefrak
--------

Y podremos ver como en la segunda sesión ya podemos ver el dato insertado por la primera:

sess2> select * from systemadmin;
+------+-------+
| id   | valor |
+------+-------+
|    1 |     2 |
+------+-------+
1 row in set (0.00 sec)

Ahora veremos como provocar un Lock wait timeout exceeded. Primero deberemos hacer un UPDATE de dicha row sin AUTOCOMMIT:

sess1> update systemadmin set valor=3 where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Veremos que en la segunda sesión si intentamos lanzar una query que modifique dicha row se queda bloqueada:

sess2> update systemadmin set valor=4;

Pero en el SHOW PROCESSLIST no veremos que exista ningún bloqueo (en State indicaría Locked si fuera MyISAM):

sess3> show full processlist;
+-------+-------------+---------------------+---------------+---------+------+----------+--------------------------------+
| Id    | User        | Host                | db            | Command | Time | State    | Info                           |
+-------+-------------+---------------------+---------------+---------+------+----------+--------------------------------+
| 29132 | whatthefrak | 172.25.10.101:49290 | battlestarG75 | Sleep   | 7260 |          | NULL                           |
| 29207 | whatthefrak | 172.25.12.22:2973   | battlestarG75 | Sleep   | 2423 |          | NULL                           |
| 29991 | root        | 127.0.0.1:50024     | jordi         | Sleep   |  289 |          | NULL                           |
| 30099 | root        | 127.0.0.1:35539     | jordi         | Query   |   14 | Updating | update systemadmin set valor=4 |
| 30100 | whatthefrak | 172.25.10.59:60375  | battlestarG75 | Sleep   |    8 |          | NULL                           |
| 30165 | root        | 127.0.0.1:37204     | NULL          | Query   |    0 | NULL     | show full processlist          |
+-------+-------------+---------------------+---------------+---------+------+----------+--------------------------------+
6 rows in set (0.00 sec)

Pero si miramos en el TRANSACTIONS del SHOW INNODB STATUS:

------------
TRANSACTIONS
------------
Trx id counter 3 1138852473
Purge done for trx's n:o < 3 1138852468 undo n:o < 0 0
History list length 1213
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1185667392
MySQL thread id 30165, query id 831313 127.0.0.1 root
show innodb status
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1204304192
MySQL thread id 29207, query id 827945 172.25.12.22 whatthefrak
---TRANSACTION 0 0, not started, process no 12825, OS thread id 1215752512
MySQL thread id 29132, query id 811974 172.25.10.101 whatthefrak
---TRANSACTION 3 1138852472, ACTIVE 6 sec, process no 12825, OS thread id 1173952832 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 30099, query id 831311 127.0.0.1 root Updating
update systemadmin set valor=4
------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 133015 page no 3 n bits 72 index `GEN_CLUST_INDEX` of table `jordi`.`systemadmin` trx id 3 1138852472 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 6; hex 0000121c4ae7; asc     J ;; 1: len 6; hex 000343e1821c; asc   C   ;; 2: len 7; hex 71000180190110; asc q      ;; 3: len 4; hex 80000001; asc     ;; 4: len 4; hex 80000003; asc     ;;

------------------
---TRANSACTION 3 1138852380, ACTIVE 416 sec, process no 12825, OS thread id 1174751552
2 lock struct(s), heap size 368, 2 row lock(s), undo log entries 1
MySQL thread id 29991, query id 831291 127.0.0.1 root

Podemos ver que se nos indica la transacción durante cuanto tiempo lleva esperando a que se libere el lock:

---TRANSACTION 3 1138852472, ACTIVE 6 sec, process no 12825, OS thread id 1173952832 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 30099, query id 831311 127.0.0.1 root Updating
update systemadmin set valor=4
------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 133015 page no 3 n bits 72 index `GEN_CLUST_INDEX` of table `jordi`.`systemadmin` trx id 3 1138852472 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 6; hex 0000121c4ae7; asc     J ;; 1: len 6; hex 000343e1821c; asc   C   ;; 2: len 7; hex 71000180190110; asc q      ;; 3: len 4; hex 80000001; asc     ;; 4: len 4; hex 80000003; asc     ;;

------------------

Como la transacción que tiene el lock:

---TRANSACTION 3 1138852380, ACTIVE 416 sec, process no 12825, OS thread id 1174751552
2 lock struct(s), heap size 368, 2 row lock(s), undo log entries 1
MySQL thread id 29991, query id 831291 127.0.0.1 root

Una vez la query espere más que innodb_lock_wait_timeout obtendremos el error:

sess2> update systemadmin set valor=4;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
sess2> 

Con estos datos siempre podríamos matar la sesión que nos esta afectando para poder realizar el UPDATE:

sess2> kill 29991;
Query OK, 0 rows affected (0.00 sec)

sess2> update systemadmin set valor=4;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Lo que implicaría la perdida de los datos no COMITEADOS de la sessión que hemos matado.