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.
Deja un comentario: