Cómo corregir un error de tiempo de espera de bloqueo excedido en MySQL

Uno de los errores más populares de InnoDB es que se excedió el tiempo de espera de bloqueo de InnoDB, por ejemplo:

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

Lo anterior simplemente significa que la transacción alcanzó innodb_lock_wait_timeout mientras esperaba obtener un bloqueo exclusivo que por defecto es de 50 segundos. Las causas comunes son:

La transacción ofensiva no es lo suficientemente rápida para confirmar o deshacer la transacción dentro de la duración innodb_lock_wait_timeout.
La transacción ofensiva está esperando que otra transacción libere el bloqueo de fila.

Los efectos de un tiempo de espera de bloqueo de InnoDB

El tiempo de espera de bloqueo de InnoDB puede causar dos implicaciones importantes:

La declaración fallida no se revierte de forma predeterminada.
Incluso si innodb_rollback_on_timeout está habilitado, cuando una instrucción falla en una transacción, ROLLBACK sigue siendo una operación más costosa que COMMIT.

Juguemos con un ejemplo simple para comprender mejor el efecto. Considere las siguientes dos tablas en la base de datos mydb:

mysql> CREATE SCHEMA mydb;
mysql> USE mydb;

La primera tabla (tabla1):

mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';

La segunda tabla (tabla2):

mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';

Ejecutamos nuestras transacciones en dos sesiones diferentes en el siguiente orden:

Pedidos	Transacción #1 (T1)	Transacción #2 (T2)
1	SELECCIONAR * DE tabla1; (OK)	SELECCIONAR * DE tabla1; (OK)
2	ACTUALIZAR table1 SET data ='T1 está actualizando la fila' WHERE id =1; (OK)
3		ACTUALIZAR table2 SET data ='T2 está actualizando la fila' WHERE id =1; (OK)
4		ACTUALIZAR table1 SET data ='T2 está actualizando la fila' WHERE id =1; (Se cuelga por un momento y finalmente devuelve un error "Se excedió el tiempo de espera de bloqueo; intente reiniciar la transacción")
5	COMMITIR; (OK)
6		COMMITIR; (OK)

Sin embargo, el resultado final después del paso n.° 6 podría ser sorprendente si no volviéramos a intentar la declaración de tiempo de espera agotado en el paso n.° 4:

mysql> SELECT * FROM table1 WHERE id = 1;
+----+-----------------------------------+
| id | data                              |
+----+-----------------------------------+
| 1  | T1 is updating the row            |
+----+-----------------------------------+



mysql> SELECT * FROM table2 WHERE id = 1;
+----+-----------------------------------+
| id | data                              |
+----+-----------------------------------+
| 1  | T2 is updating the row            |
+----+-----------------------------------+

Después de que T2 se comprometiera con éxito, uno esperaría obtener el mismo resultado "T2 está actualizando la fila" tanto para la tabla 1 como para la tabla 2, pero los resultados muestran que solo se actualizó la tabla 2. Uno podría pensar que si se encuentra algún error dentro de una transacción, todas las declaraciones en la transacción se revertirán automáticamente, o si una transacción se confirma con éxito, todas las declaraciones se ejecutarán atómicamente. Esto es cierto para el interbloqueo, pero no para el tiempo de espera de bloqueo de InnoDB.

A menos que configure innodb_rollback_on_timeout=1 (el valor predeterminado es 0 - deshabilitado), la reversión automática no ocurrirá para el error de tiempo de espera de bloqueo de InnoDB. Esto significa que, al seguir la configuración predeterminada, MySQL no fallará y revertirá toda la transacción, ni volverá a intentar la declaración agotada y solo procesará las siguientes declaraciones hasta que llegue a COMMIT o ROLLBACK. ¡Esto explica por qué la transacción T2 se comprometió parcialmente!

La documentación de InnoDB dice claramente "InnoDB revierte solo la última declaración en el tiempo de espera de una transacción por defecto". En este caso, no obtenemos la atomicidad de la transacción que ofrece InnoDB. La atomicidad en cumplimiento con ACID es que obtenemos todo o nada de la transacción, lo que significa que la transacción parcial es simplemente inaceptable.

Lidiar con un tiempo de espera de bloqueo de InnoDB

Por lo tanto, si espera que una transacción se revierta automáticamente cuando se encuentra con un error de espera de bloqueo de InnoDB, similar a lo que sucedería en un punto muerto, configure la siguiente opción en el archivo de configuración de MySQL:

innodb_rollback_on_timeout=1

Se requiere un reinicio de MySQL. Al implementar un clúster basado en MySQL, ClusterControl siempre establecerá innodb_rollback_on_timeout=1 en cada nodo. Sin esta opción, su aplicación debe volver a intentar la declaración fallida o realizar ROLLBACK explícitamente para mantener la atomicidad de la transacción.

Para verificar si la configuración se carga correctamente:

mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON    |
+----------------------------+-------+

Para verificar si la nueva configuración funciona, podemos rastrear el contador com_rollback cuando ocurre este error:

mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback  | 1     |
+---------------+-------+

Seguimiento de la transacción de bloqueo

Hay varios lugares en los que podemos buscar para rastrear la transacción o las declaraciones de bloqueo. Comencemos mirando el estado del motor InnoDB en la sección TRANSACCIONES:

mysql> SHOW ENGINE INNODB STATUS\G
------------
TRANSACTIONS
------------

...

---TRANSACTION 3100, ACTIVE 2 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 50, OS thread handle 139887555282688, query id 360 localhost ::1 root updating
update table1 set data = 'T2 is updating the row' where id = 1

------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 4 n bits 72 index PRIMARY of table `mydb`.`table1` trx id 3100 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000000c19; asc       ;;
 2: len 7; hex 020000011b0151; asc       Q;;
 3: len 22; hex 5431206973207570646174696e672074686520726f77; asc T1 is updating the row;;
------------------

---TRANSACTION 3097, ACTIVE 46 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 48, OS thread handle 139887556167424, query id 358 localhost ::1 root
Trx read view will not see trx with id >= 3097, sees < 3097

A partir de la información anterior, podemos obtener una descripción general de las transacciones que están actualmente activas en el servidor. La transacción 3097 actualmente está bloqueando una fila a la que debe acceder la transacción 3100. Sin embargo, el resultado anterior no nos dice el texto de consulta real que podría ayudarnos a determinar qué parte de la consulta/declaración/transacción necesitamos investigar más a fondo. . Usando el bloqueador MySQL thread ID 48, veamos qué podemos recopilar de la lista de procesos de MySQL:

mysql> SHOW FULL PROCESSLIST;
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| Id | User            | Host            | db                 | Command | Time | State                  | Info                  |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| 4  | event_scheduler | localhost       | <null>             | Daemon  | 5146 | Waiting on empty queue | <null>                |
| 10 | root            | localhost:56042 | performance_schema | Query   | 0    | starting               | show full processlist |
| 48 | root            | localhost:56118 | mydb               | Sleep   | 145  |                        | <null>                |
| 50 | root            | localhost:56122 | mydb               | Sleep   | 113  |                        | <null>                |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+

Thread ID 48 muestra el comando como 'Dormir'. Aún así, esto no nos ayuda mucho para saber qué declaraciones bloquean la otra transacción. Esto se debe a que la declaración en esta transacción se ha ejecutado y esta transacción abierta básicamente no hace nada en este momento. Necesitamos profundizar más para ver qué está pasando con este hilo.

Para MySQL 8.0, la instrumentación de espera de bloqueo de InnoDB está disponible en la tabla data_lock_waits dentro de la base de datos performance_schema (o en la tabla innodb_lock_waits dentro de la base de datos sys). Si se está produciendo un evento de espera de bloqueo, deberíamos ver algo como esto:

mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE                           | INNODB
REQUESTING_ENGINE_LOCK_ID        | 139887595270456:6:4:2:139887487554680
REQUESTING_ENGINE_TRANSACTION_ID | 3100
REQUESTING_THREAD_ID             | 89
REQUESTING_EVENT_ID              | 8
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487554680
BLOCKING_ENGINE_LOCK_ID          | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID   | 3097
BLOCKING_THREAD_ID               | 87
BLOCKING_EVENT_ID                | 9
BLOCKING_OBJECT_INSTANCE_BEGIN   | 139887487548648

Tenga en cuenta que en MySQL 5.6 y 5.7, la información similar se almacena dentro de la tabla innodb_lock_waits en la base de datos information_schema. Preste atención al valor BLOCKING_THREAD_ID. Podemos usar esta información para buscar todas las declaraciones que ejecuta este hilo en la tabla events_statements_history:

mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in set

Parece que la información del hilo ya no está allí. Podemos verificar comprobando el valor mínimo y máximo de la columna thread_id en la tabla events_statements_history con la siguiente consulta:

mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98               | 129              |
+------------------+------------------+

El subproceso que buscábamos (87) se ha truncado de la tabla. Podemos confirmar esto observando el tamaño de la tabla event_statements_history:

mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10                                                  |
+-----------------------------------------------------+

Lo anterior significa que events_statements_history solo puede almacenar los últimos 10 subprocesos. Afortunadamente, performance_schema tiene otra tabla para almacenar más filas llamada events_statements_history_long, que almacena información similar pero para todos los subprocesos y puede contener muchas más filas:

mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000                                                    |
+----------------------------------------------------------+

Sin embargo, obtendrá un resultado vacío si intenta consultar la tabla events_statements_history_long por primera vez. Esto es de esperar porque, de forma predeterminada, esta instrumentación está deshabilitada en MySQL, como podemos ver en la siguiente tabla setup_consumers:

mysql> SELECT * FROM performance_schema.setup_consumers;
+----------------------------------+---------+
| NAME                             | ENABLED |
+----------------------------------+---------+
| events_stages_current            | NO      |
| events_stages_history            | NO      |
| events_stages_history_long       | NO      |
| events_statements_current        | YES     |
| events_statements_history        | YES     |
| events_statements_history_long   | NO      |
| events_transactions_current      | YES     |
| events_transactions_history      | YES     |
| events_transactions_history_long | NO      |
| events_waits_current             | NO      |
| events_waits_history             | NO      |
| events_waits_history_long        | NO      |
| global_instrumentation           | YES     |
| thread_instrumentation           | YES     |
| statements_digest                | YES     |
+----------------------------------+---------+

Para activar la tabla events_statements_history_long, necesitamos actualizar la tabla setup_consumers como se muestra a continuación:

mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';

Verifique si hay filas en la tabla events_statements_history_long ahora:

mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4                  |
+--------------------+

Frio. Ahora podemos esperar hasta que el evento de espera de bloqueo de InnoDB vuelva a surgir y cuando suceda, debería ver la siguiente fila en la tabla data_lock_waits:

mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE                           | INNODB
REQUESTING_ENGINE_LOCK_ID        | 139887595270456:6:4:2:139887487555024
REQUESTING_ENGINE_TRANSACTION_ID | 3083
REQUESTING_THREAD_ID             | 60
REQUESTING_EVENT_ID              | 9
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487555024
BLOCKING_ENGINE_LOCK_ID          | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID   | 3081
BLOCKING_THREAD_ID               | 57
BLOCKING_EVENT_ID                | 8
BLOCKING_OBJECT_INSTANCE_BEGIN   | 139887487548648

Nuevamente, usamos el valor BLOCKING_THREAD_ID para filtrar todas las instrucciones que ha ejecutado este hilo en la tabla events_statements_history_long:

mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` FROM events_statements_history_long 
WHERE `THREAD_ID` = 57
ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME            | CURRENT_SCHEMA | SQL_TEXT                                                       |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57        | 1        | statement/sql/select  | <null>         | select connection_id()                                         |
| 57        | 2        | statement/sql/select  | <null>         | SELECT @@VERSION                                               |
| 57        | 3        | statement/sql/select  | <null>         | SELECT @@VERSION_COMMENT                                       |
| 57        | 4        | statement/com/Init DB | <null>         | <null>                                                         |
| 57        | 5        | statement/sql/begin   | mydb           | begin                                                          |
| 57        | 7        | statement/sql/select  | mydb           | select 'T1 is in the house'                                    |
| 57        | 8        | statement/sql/select  | mydb           | select * from table1                                           |
| 57        | 9        | statement/sql/select  | mydb           | select 'some more select'                                      |
| 57        | 10       | statement/sql/update  | mydb           | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Finalmente, encontramos al culpable. Al observar la secuencia de eventos del subproceso 57, podemos saber dónde la transacción anterior (T1) aún no ha finalizado (sin COMMIT o ROLLBACK), y podemos ver que la última declaración obtuvo un bloqueo exclusivo para la fila para actualización operación que necesitaba la otra transacción (T2) y simplemente colgando allí. Eso explica por qué vemos 'Dormir' en la salida de la lista de procesos de MySQL.

Como podemos ver, la declaración SELECT anterior requiere que obtenga el valor thread_id de antemano. Para simplificar esta consulta, podemos usar la cláusula IN y una subconsulta para unir ambas tablas. La siguiente consulta produce un resultado idéntico al anterior:

mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` from events_statements_history_long WHERE `THREAD_ID` IN (SELECT `BLOCKING_THREAD_ID` FROM data_lock_waits) ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME            | CURRENT_SCHEMA | SQL_TEXT                                                       |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57        | 1        | statement/sql/select  | <null>         | select connection_id()                                         |
| 57        | 2        | statement/sql/select  | <null>         | SELECT @@VERSION                                               |
| 57        | 3        | statement/sql/select  | <null>         | SELECT @@VERSION_COMMENT                                       |
| 57        | 4        | statement/com/Init DB | <null>         | <null>                                                         |
| 57        | 5        | statement/sql/begin   | mydb           | begin                                                          |
| 57        | 7        | statement/sql/select  | mydb           | select 'T1 is in the house'                                    |
| 57        | 8        | statement/sql/select  | mydb           | select * from table1                                           |
| 57        | 9        | statement/sql/select  | mydb           | select 'some more select'                                      |
| 57        | 10       | statement/sql/update  | mydb           | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Sin embargo, no es práctico para nosotros ejecutar la consulta anterior siempre que ocurra un evento de espera de bloqueo de InnoDB. Además del error de la aplicación, ¿cómo sabría que está ocurriendo el evento de espera de bloqueo? Podemos automatizar la ejecución de esta consulta con el siguiente script Bash simple, llamado track_lockwait.sh:

$ cat track_lockwait.sh
#!/bin/bash
## track_lockwait.sh
## Print out the blocking statements that causing InnoDB lock wait

INTERVAL=5
DIR=/root/lockwait/

[ -d $dir ] || mkdir -p $dir

while true; do
  check_query=$(mysql -A -Bse 'SELECT THREAD_ID,EVENT_ID,EVENT_NAME,CURRENT_SCHEMA,SQL_TEXT FROM events_statements_history_long WHERE THREAD_ID IN (SELECT BLOCKING_THREAD_ID FROM data_lock_waits) ORDER BY EVENT_ID')

  # if $check_query is not empty
  if [[ ! -z $check_query ]]; then
    timestamp=$(date +%s)
    echo $check_query > $DIR/innodb_lockwait_report_${timestamp}
  fi

  sleep $INTERVAL
done

Aplicar permiso ejecutable y demonizar el script en segundo plano:

$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &

Ahora, solo tenemos que esperar a que se generen los informes en el directorio /root/lockwait. Según la carga de trabajo de la base de datos y los patrones de acceso a las filas, es posible que vea muchos archivos en este directorio. Supervise el directorio de cerca; de lo contrario, se inundaría con demasiados archivos de informes.

Si está utilizando ClusterControl, puede habilitar la función Registro de transacciones en Rendimiento -> Registro de transacciones, donde ClusterControl proporcionará un informe sobre bloqueos y transacciones de ejecución prolongada que facilitarán su vida para encontrar al culpable.

Conclusión

En resumen, si nos enfrentamos a un error de "Tiempo de espera de espera de bloqueo excedido" en MySQL, primero debemos comprender los efectos que dicho error puede tener en nuestra infraestructura, luego rastrear la transacción ofensiva y actuar en consecuencia. ya sea con scripts de shell como track_lockwait.sh, o software de administración de bases de datos como ClusterControl.

Si decide utilizar secuencias de comandos de shell, tenga en cuenta que pueden ahorrarle dinero pero le costarán tiempo, ya que necesitará saber un par de cosas sobre cómo funcionan, envíe su solicitud. permisos, y posiblemente hacer que se ejecuten en segundo plano, y si te pierdes en la jungla de shell, podemos ayudarte.

Independientemente de lo que decida implementar, asegúrese de seguirnos en Twitter o suscríbase a nuestro feed RSS para obtener más consejos sobre cómo mejorar el rendimiento tanto de su software como de las bases de datos que lo respaldan, como esta publicación que cubre 6 escenarios de fallas comunes en MySQL.