Como corrigir um erro de tempo limite de espera de bloqueio excedido no MySQL

Um dos erros mais populares do InnoDB é o tempo limite de espera de bloqueio do InnoDB excedido, por exemplo:

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

O acima significa simplesmente que a transação atingiu o innodb_lock_wait_timeout enquanto aguardava para obter um bloqueio exclusivo cujo padrão é 50 segundos. As causas comuns são:

A transação ofensiva não é rápida o suficiente para confirmar ou reverter a transação dentro da duração innodb_lock_wait_timeout.
A transação ofensiva está aguardando que o bloqueio de linha seja liberado por outra transação.

Os efeitos de um tempo limite de espera de bloqueio do InnoDB

O tempo limite de espera do bloqueio do InnoDB pode causar duas implicações principais:

A instrução com falha não está sendo revertida por padrão.
Mesmo se innodb_rollback_on_timeout estiver habilitado, quando uma instrução falha em uma transação, ROLLBACK ainda é uma operação mais cara que COMMIT.

Vamos brincar com um exemplo simples para entender melhor o efeito. Considere as duas tabelas a seguir no banco de dados mydb:

mysql> CREATE SCHEMA mydb;
mysql> USE mydb;

A primeira tabela (tabela1):

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

A segunda tabela (tabela2):

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

Executamos nossas transações em duas sessões diferentes na seguinte ordem:

Pedido	Transação nº 1 (T1)	Transação nº 2 (T2)
1	SELECT * FROM table1; (OK)	SELECT * FROM table1; (OK)
2	UPDATE table1 SET data ='T1 está atualizando a linha' WHERE id =1; (OK)
3		UPDATE table2 SET data ='T2 está atualizando a linha' WHERE id =1; (OK)
4		UPDATE table1 SET data ='T2 está atualizando a linha' WHERE id =1; (Trava por um tempo e eventualmente retorna um erro "Tempo limite de espera de bloqueio excedido; tente reiniciar a transação")
5	COMMIT; (OK)
6		COMMIT; (OK)

No entanto, o resultado final após a etapa #6 pode ser surpreendente se não tentarmos novamente a instrução expirada na etapa #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            |
+----+-----------------------------------+

Depois que T2 foi confirmado com sucesso, seria de se esperar obter a mesma saída "T2 está atualizando a linha" para tabela1 e tabela2, mas os resultados mostram que apenas a tabela2 foi atualizada. Pode-se pensar que, se algum erro for encontrado em uma transação, todas as instruções na transação serão automaticamente revertidas ou, se uma transação for confirmada com sucesso, todas as instruções serão executadas atomicamente. Isso é verdade para deadlock, mas não para o tempo limite de espera de bloqueio do InnoDB.

A menos que você defina innodb_rollback_on_timeout=1 (o padrão é 0 - desabilitado), a reversão automática não acontecerá para o erro de tempo limite de espera de bloqueio do InnoDB. Isso significa que, seguindo a configuração padrão, o MySQL não falhará e reverterá toda a transação, nem tentará novamente a instrução expirada e apenas processará as próximas instruções até atingir COMMIT ou ROLLBACK. Isso explica por que a transação T2 foi parcialmente confirmada!

A documentação do InnoDB diz claramente "O InnoDB reverte apenas a última instrução em um tempo limite de transação por padrão". Nesse caso, não obtemos a atomicidade da transação oferecida pelo InnoDB. A atomicidade em conformidade com ACID é obter tudo ou nada da transação, o que significa que a transação parcial é meramente inaceitável.

Lidando com um tempo limite de espera de bloqueio do InnoDB

Portanto, se você espera que uma transação seja revertida automaticamente quando encontrar um erro de espera de bloqueio do InnoDB, semelhante ao que aconteceria em um impasse, defina a seguinte opção no arquivo de configuração do MySQL:

innodb_rollback_on_timeout=1

Uma reinicialização do MySQL é necessária. Ao implantar um cluster baseado em MySQL, o ClusterControl sempre definirá innodb_rollback_on_timeout=1 em cada nó. Sem essa opção, seu aplicativo precisa tentar novamente a instrução com falha ou executar ROLLBACK explicitamente para manter a atomicidade da transação.

Para verificar se a configuração foi carregada corretamente:

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

Para verificar se a nova configuração funciona, podemos rastrear o contador com_rollback quando esse erro ocorrer:

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

Acompanhando a transação de bloqueio

Existem vários lugares que podemos procurar para rastrear a transação ou as instruções de bloqueio. Vamos começar examinando o status do mecanismo InnoDB na seção TRANSACTIONS:

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 das informações acima, podemos obter uma visão geral das transações que estão atualmente ativas no servidor. A transação 3097 está atualmente bloqueando uma linha que precisa ser acessada pela transação 3100. No entanto, a saída acima não nos informa o texto da consulta real que pode nos ajudar a descobrir qual parte da consulta/instrução/transação precisamos investigar mais a fundo . Usando o ID de thread 48 do bloqueador MySQL, vamos ver o que podemos coletar da lista de processos do 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 mostra o comando como 'Sleep'. Ainda assim, isso não nos ajuda muito a saber quais declarações bloqueiam a outra transação. Isso ocorre porque a instrução nesta transação foi executada e essa transação aberta basicamente não está fazendo nada no momento. Precisamos mergulhar mais fundo para ver o que está acontecendo com este tópico.

Para o MySQL 8.0, a instrumentação de espera de bloqueio do InnoDB está disponível na tabela data_lock_waits dentro do banco de dados performance_schema (ou tabela innodb_lock_waits dentro do banco de dados sys). Se um evento de espera de bloqueio estiver acontecendo, devemos ver algo assim:

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

Observe que no MySQL 5.6 e 5.7, as informações semelhantes são armazenadas dentro da tabela innodb_lock_waits no banco de dados information_schema. Preste atenção ao valor BLOCKING_THREAD_ID. Podemos usar esta informação para procurar todas as instruções que estão sendo executadas por este thread na tabela events_statements_history:

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

Parece que as informações do tópico não estão mais lá. Podemos verificar verificando o valor mínimo e máximo da coluna thread_id na tabela events_statements_history com a seguinte consulta:

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

O segmento que estávamos procurando (87) foi truncado da tabela. Podemos confirmar isso observando o tamanho da tabela event_statements_history:

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

O acima significa que o events_statements_history só pode armazenar os últimos 10 threads. Felizmente, performance_schema tem outra tabela para armazenar mais linhas chamada events_statements_history_long, que armazena informações semelhantes, mas para todos os threads e pode conter muito mais linhas:

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

No entanto, você obterá um resultado vazio se tentar consultar a tabela events_statements_history_long pela primeira vez. Isso é esperado porque, por padrão, essa instrumentação está desabilitada no MySQL, como podemos ver na seguinte tabela 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 ativar a tabela events_statements_history_long, precisamos atualizar a tabela setup_consumers conforme abaixo:

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

Verifique se há linhas na tabela events_statements_history_long agora:

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

Frio. Agora podemos esperar até que o evento de espera de bloqueio do InnoDB seja gerado novamente e, quando isso estiver acontecendo, você deverá ver a seguinte linha na tabela 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

Novamente, usamos o valor BLOCKING_THREAD_ID para filtrar todas as instruções que foram executadas por este thread na tabela 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 o culpado. Podemos dizer olhando para a sequência de eventos do thread 57 onde a transação acima (T1) ainda não terminou (sem COMMIT ou ROLLBACK), e podemos ver que a última instrução obteve um bloqueio exclusivo para a linha para atualização operação que precisava da outra transação (T2) e apenas pendurada lá. Isso explica por que vemos 'Sleep' na saída da lista de processos do MySQL.

Como podemos ver, a instrução SELECT acima exige que você obtenha o valor thread_id antecipadamente. Para simplificar essa consulta, podemos usar a cláusula IN e uma subconsulta para unir as duas tabelas. A consulta a seguir produz um resultado idêntico ao acima:

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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

No entanto, não é prático para nós executar a consulta acima sempre que o evento de espera de bloqueio do InnoDB ocorrer. Além do erro do aplicativo, como você saberia que o evento de espera de bloqueio está acontecendo? Podemos automatizar essa execução de consulta com o seguinte script Bash simples, chamado 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

Aplique permissão executável e daemonize o script em segundo plano:

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

Agora, só precisamos esperar que os relatórios sejam gerados no diretório /root/lockwait. Dependendo da carga de trabalho do banco de dados e dos padrões de acesso à linha, você provavelmente verá muitos arquivos nesse diretório. Monitore o diretório de perto, caso contrário, ele seria inundado com muitos arquivos de relatório.

Se você estiver usando o ClusterControl, você pode habilitar o recurso de log de transações em Desempenho -> Log de transações, onde o ClusterControl fornecerá um relatório sobre impasses e transações de longa duração que facilitarão sua vida para encontrar o culpado.

Conclusão

Em resumo, se nos depararmos com um erro “Lock Wait Timeout Exceeded” no MySQL, precisamos primeiro entender os efeitos que tal erro pode ter em nossa infraestrutura, então rastrear a transação ofensiva e agir seja com scripts de shell como track_lockwait.sh ou software de gerenciamento de banco de dados como ClusterControl.

Se você decidir usar scripts de shell, lembre-se de que eles podem economizar dinheiro, mas custarão tempo, pois você precisa saber algumas coisas sobre como eles funcionam, inscreva-se permissões, e possivelmente fazê-los rodar em segundo plano, e se você se perder na selva de conchas, nós podemos ajudar.

O que quer que você decida implementar, certifique-se de nos seguir no Twitter ou assinar nosso feed RSS para obter mais dicas sobre como melhorar o desempenho do seu software e dos bancos de dados que o suportam, como este post cobrindo 6 cenários de falhas comuns no MySQL.