Como rastrear deadlocks no Firebird

Alexey Kovyazin, 08-May-2019, (c) IBSurgeon

Conflitos de atualização (frequentemente chamados de «deadlocks») ocorrem em aplicações Firebird que realizam atualizações concorrentes intensivas de dados.

Como você pode ver no artigo « Transactions in Firebird», existem 3 tipos de erros que contêm a palavra-chave «deadlock»:

Code

deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

lock time-out on wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

lock conflict on no wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN

Todos os 3 tipos de conflitos de atualização têm em comum o fato de que o conflito de atualização geralmente é o resultado de 2 operações de modificação que tentam modificar o mesmo registro.

As opções possíveis são as seguintes: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

É relativamente fácil rastrear a operação «vítima», que recebe a mensagem de erro - basta colocá-la em try… catch e registrar os parâmetros usados na consulta que falha com o erro.

No entanto, com essa abordagem, é difícil rastrear o «vencedor» - ou seja, a transação concorrente onde a atualização foi feita com sucesso, sem erro.

Para ajudar os desenvolvedores a investigar conflitos de atualização, o Firebird coloca nas mensagens de erro a referência à transação concorrente - ou seja, a transação onde a atualização concorrente ainda não foi confirmada. Juntamente com a Trace API, isso nos dá a capacidade de rastrear ambas as operações conflitantes.

Vamos considerar os passos práticos de como fazer isso.

Primeiro, precisamos configurar o rastreamento. Para isso, crie o arquivo de texto (no nosso caso, é C:\Temp\mytrace.conf) com o seguinte conteúdo:

Code

database
{
	enabled = true
	include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"
	log_statement_finish = true
	log_errors = true
	include_gds_codes="deadlock"
	log_initfini = false
	time_threshold = 0
	max_sql_length = 65000

}

O arquivo de configuração acima habilita o rastreamento para todos os bancos de dados, então se você tiver mais de 1 banco de dados ativo, é melhor especificar o nome do banco de dados no arquivo de configuração, ou seja:

Code

Database=mydatabase.fdb
{
  enabled = true
…
}

Vamos revisar os parâmetros mais importantes no arquivo de configuração:

Parâmetro include filter

Code

include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"

Isso significa que queremos rastrear apenas declarações UPDATE e DELETE e ignorar selects. É necessário filtrar o máximo possível de declarações, porque no sistema de produção sob alta carga, a quantidade de registros no log de texto pode ser muito alta para analisar.

Geralmente, sabemos qual tabela está participando do conflito de atualização; uma boa ideia será colocá-la no filtro, para reduzir o número de atualizações a analisar:

Code

include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%WITH lock%)|(UPDATE OR INSERT INTO T1%)"

E se as atualizações e exclusões forem feitas por stored procedures? Bem, isso torna todo o processo mais difícil: adicione ao filtro todas as stored procedures que podem estar envolvidas em atualizações concorrentes, e também habilite o registro de procedures:

Code

include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%with lock%)|(UPDATE OR INSERT INTO T1%)|(%SP_UPDATE_T1%)|(%SP_DEL_T1%)"
log_procedures=true

Parâmetros de registro de erros

Em seguida, precisamos especificar o registro de erros e limitá-lo aos deadlocks.

Code

log_errors = true
include_gds_codes="deadlock"

Por favor, observe: o parâmetro include_gds_codes apareceu apenas no Firebird 3.0.2, então se você usar 2.5 ou 3.0.0 ou 3.0.1, não é possível filtrar apenas erros de deadlock, então todos os erros serão impressos no log.

Demonstração

Para demonstrar o processo geral, vamos preparar o banco de dados de teste - por simplicidade, haverá 1 tabela com 1 coluna de chave primária.

Code

C:\HQbird\Firebird30>isql
Use CONNECT or CREATE DATABASE to specify a database
SQL> create database "c:\temp\testdeadlock.fdb" user "SYSDBA" password "masterkey";
SQL> create table t1(i1 integer not null primary key);
SQL> insert into t1(i1) values(1);
SQL> commit; exit;

Depois disso, precisamos iniciar a sessão de rastreamento:

Code

fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\mytrace.conf" -user SYSDBA -pass masterkey

Neste caso, o fbtracemgr imprime o log na tela, mas na produção, precisamos redirecioná-lo para o arquivo, é claro.

Após o início bem-sucedido, o fbtracemgr imprime algo assim:

Code

Trace session ID 4 started

Em seguida, vamos iniciar 2 sessões isql e tentar simular o conflito de atualização. Na tabela abaixo, temos 2 colunas para 2 sessões isql. Cada linha representa um momento no tempo em que os comandos foram executados.


Tempo	sessão isql 1	sessão isql 2
T1	`<br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 15<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br>`
T2		`<br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 20<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br>`
Então, no ponto inicial, podemos ver que 2 transações foram iniciadas, #15 e #20. Em seguida, vamos tentar realizar a atualização concorrente do mesmo registro:

T3	`<br>SQL> UPDATE T1 SET i1=5 where i1=2;<br>`
T4		`<br>SQL> UPDATE T1 SET i1=100 where i1=2;<br>`
T5	`<br>SQL> commit;<br>SQL><br>`	`<br>Statement failed, SQLSTATE = 40001<br>deadlock<br>-update conflicts with concurrent update<br>-concurrent transaction number is 15<br>SQL><br>`

Iniciamos o UPDATE na sessão 1, mas não o confirmamos.

Na sessão 2, o UPDATE «pendurou» - ele esperou pelo fim da transação concorrente, e quando confirmamos o UPDATE na sessão 1, a sessão 2 recebeu o erro:

Code

Statement failed, SQLSTATE = 40001
deadlock
-update conflicts with concurrent update
-concurrent transaction number is 15
SQL>

Então, temos uma situação típica em caso de conflito de atualização com transação de espera.

Vamos revisar o log de rastreamento para encontrar as evidências do conflito de atualização.

Neste caso, o log de rastreamento é muito curto, mas no caso do sistema de produção, pode ser muito mais longo, mas a abordagem para encontrar deadlocks é a mesma.

Code

fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\fbtrace.conf" -user SYSDBA -pass masterkey
Trace session ID 4 started

2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
        C:\HQbird\Firebird30\isql.exe:8828
                (TRA_15, CONCURRENCY | WAIT | READ_WRITE)

Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
      0 ms, 2 read(s), 21 fetch(es), 3 mark(s)

2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
                (TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
  40242 ms, 19 fetch(es), 2 mark(s)

2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15

Como você pode ver, temos registros no log sobre ambas as atualizações - bem-sucedida e falha, e uma mensagem de erro sobre deadlock.

Vamos considerar como analisar o log:

Na mensagem de erro, vamos localizar o identificador da transação:

Code

 2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15

Perto do registro sobre o erro (geralmente logo acima dele), você verá a declaração que falhou:

Code

2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
        C:\HQbird\Firebird30\isql.exe:7032
                (TRA_20, CONCURRENCY | WAIT | READ_WRITE)

Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
  40242 ms, 19 fetch(es), 2 mark(s)

Observe que o tempo de execução é enorme (~40 segundos) - isso indica o tempo em que a operação aguardou o resultado da transação concorrente.

E, finalmente, procure o número da transação com a operação UPDATE bem-sucedida: para isso, localize TRA_NNN, onde NNN é o número da transação. No nosso caso, será TRA_15:

Code

2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
        C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
        C:\HQbird\Firebird30\isql.exe:8828
                (TRA_15, CONCURRENCY | WAIT | READ_WRITE)

Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
      0 ms, 2 read(s), 21 fetch(es), 3 mark(s)

Então, é isso - encontramos ambas as partes do conflito de atualização - a bem-sucedida e a que falhou.

Ferramentas para identificar deadlocks

Como você pode ver, pode ser bastante difícil identificar a fonte raiz do conflito de bloqueio/deadlock: como o conflito sempre tem 2 lados, e um lado “vence” (conclui sem mensagens de erro), pode ser complicado identificar o vencedor. Por exemplo, o conflito pode acontecer dentro de EXECUTE STATEMENT, ou em uma stored procedure aninhada, ou dentro de um trigger, ou pode ser uma combinação de todas essas coisas.

Para identificar deadlocks, a IBSurgeon desenvolveu a ferramenta “Deadlock Analyzer”, que analisa o log de rastreamento e cria diagramas fáceis de entender com detalhes das chamadas que levaram aos deadlocks. Esta ferramenta está disponível como parte da Enterprise Subscription (tem versão de teste) - registre-se em cc.ib-aid.com.

Além disso, a HQbird apresenta uma versão estendida do plugin fbtrace, que pode ser configurada para salvar apenas alterações e tentativas de alterações (ou seja, operações que falharam e conflitos de bloqueio e deadlocks).

Entre em contato com o suporte da IBSurgeon para obter mais informações: [email protected].

Como evitar deadlocks?

Agora você precisa identificar a melhor solução para sua aplicação evitar deadlocks - pode ser uma mudança nos parâmetros da transação, ou é possível adicionar processamento extra de erros e repetir a operação ou realizar verificações adicionais no nível de negócios da aplicação.