Come tracciare i deadlock in Firebird

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

I conflitti di aggiornamento (spesso chiamati «deadlock») si verificano nelle applicazioni Firebird che eseguono aggiornamenti concorrenti intensivi dei dati.

Come si può vedere dall’articolo « Transactions in Firebird», ci sono 3 tipi di errori che contengono la parola chiave «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

Tutti e 3 i tipi di conflitti di aggiornamento hanno in comune il fatto che il conflitto di aggiornamento di solito è il risultato di 2 operazioni di modifica che tentano di modificare lo stesso record.

Le opzioni possibili sono le seguenti: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

È relativamente facile tracciare l’operazione «vittima», che riceve il messaggio di errore - basta inserirla in try… catch e registrare i parametri utilizzati nella query che fallisce con l’errore.

Tuttavia, con questo approccio, è difficile tracciare il «vincitore» - cioè, la transazione concorrente in cui l’aggiornamento è stato eseguito con successo, senza errori.

Per aiutare gli sviluppatori a indagare sui conflitti di aggiornamento, Firebird inserisce nei messaggi di errore il riferimento alla transazione concorrente - cioè, la transazione in cui l’aggiornamento concorrente non è ancora stato committato. Insieme alla Trace API, questo ci dà la capacità di tracciare entrambe le operazioni in conflitto.

Consideriamo i passi pratici su come farlo.

Prima di tutto, dobbiamo configurare la tracciatura. Per questo, crea il file di testo (nel nostro caso è C:\Temp\mytrace.conf) con il seguente contenuto:

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

}

Il file di configurazione sopra abilita la tracciatura per tutti i database, quindi se hai più di 1 database attivo, è meglio specificare il nome del database nel file di configurazione, cioè:

Code

Database=mydatabase.fdb
{
  enabled = true
…
}

Rivediamo i parametri più importanti nel file di configurazione:

Parametro include filter

Code

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

Significa che vogliamo tracciare solo le istruzioni UPDATE e DELETE e ignorare le select. È necessario filtrare quante più istruzioni possibile, perché nel sistema di produzione sotto carico elevato la quantità di record nel log di testo può essere troppo alta da analizzare.

Di solito, sappiamo quale tabella partecipa al conflitto di aggiornamento, la buona idea sarà inserirla nel filtro, per ridurre il numero di aggiornamenti da analizzare:

Code

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

E se gli aggiornamenti e le eliminazioni vengono eseguiti da stored procedure? Beh, rende l’intero processo più difficile: aggiungi al filtro tutte le stored procedure che possono essere coinvolte negli aggiornamenti concorrenti, e abilita anche la registrazione delle procedure:

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

Parametri di registrazione degli errori

Poi, dobbiamo specificare la registrazione degli errori e limitarla ai deadlock.

Code

log_errors = true
include_gds_codes="deadlock"

Per favore nota: il parametro include_gds_codes è apparso solo in Firebird 3.0.2, quindi se usi 2.5 o 3.0.0 o 3.0.1, non è possibile filtrare solo gli errori di deadlock, quindi tutti gli errori verranno stampati nel log.

Dimostrazione

Per dimostrare l’intero processo, prepariamo il database di test - per semplicità, ci sarà 1 tabella con 1 colonna primaria.

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;

Dopo di che, dobbiamo avviare la sessione di traccia:

Code

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

In questo caso, fbtracemgr stampa il log sullo schermo, ma in produzione, dobbiamo reindirizzarlo al file, ovviamente.

Dopo l’avvio riuscito, fbtracemgr stampa qualcosa del genere:

Code

Trace session ID 4 started

Poi, avviamo 2 sessioni isql e proviamo a simulare il conflitto di aggiornamento. Nella tabella sottostante abbiamo 2 colonne per 2 sessioni isql. Ogni riga rappresenta un momento nel tempo in cui i comandi sono stati eseguiti.


Tempo	sessione isql 1	sessione 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>`
Quindi, al punto di partenza, possiamo vedere che sono avviate 2 transazioni, #15 e #20. Poi, proviamo a eseguire l’aggiornamento concorrente dello stesso record:

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

Abbiamo avviato UPDATE nella sessione 1 ma non l’abbiamo committato.

Nella sessione 2, UPDATE «si è bloccato» - ha atteso la fine della transazione concorrente, e quando abbiamo committato UPDATE nella sessione 1, la sessione 2 ha ricevuto l’errore:

Code

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

Quindi, abbiamo una situazione tipica in caso di conflitto di aggiornamento con transazione in attesa.

Rivediamo il log di traccia per trovare le prove del conflitto di aggiornamento.

In questo caso, il log di traccia è molto breve, ma nel caso del sistema di produzione, può essere molto più lungo, ma l’approccio per trovare i deadlock è lo stesso.

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

Come puoi vedere, abbiamo record nel log su entrambi gli aggiornamenti - riuscito e fallito, e un messaggio di errore sul deadlock.

Consideriamo come analizzare il log:

Nel messaggio di errore, individuiamo l’identificatore della transazione:

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

Vicino al record sull’errore (di solito subito sopra), vedrai l’istruzione fallita:

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)

Nota che il tempo di esecuzione è enorme (~40 secondi)- indica il tempo in cui l’operazione ha atteso il risultato della transazione concorrente.

E, infine, cerca il numero di transazione con l’operazione UPDATE riuscita: per questo, individua TRA_NNN, dove NNN è il numero di transazione. Nel nostro caso, sarà 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)

Quindi, questo è tutto - abbiamo trovato entrambe le parti del conflitto di aggiornamento - quella riuscita e quella fallita.

Strumenti per identificare i deadlock

Come puoi vedere, può essere piuttosto difficile identificare la fonte principale del conflitto di lock/deadlock: poiché il conflitto ha sempre 2 lati, e un lato “vince” (completa senza messaggi di errore), può essere complicato identificare il vincitore. Per esempio, il conflitto può accadere dentro EXECUTE STATEMENT, o nella stored procedure annidata, o dentro un trigger, o potrebbe essere una combinazione di tutte queste cose.

Per identificare i deadlock, IBSurgeon ha sviluppato lo strumento “Deadlock Analyzer”, che analizza il log di traccia e crea diagrammi facili da capire con dettagli delle chiamate che hanno portato ai deadlock. Questo strumento è disponibile come parte dell’Enterprise Subscription (ha una prova) - registrati su cc.ib-aid.com.

Inoltre, HQbird introduce una versione estesa del plugin fbtrace, che può essere configurato per salvare solo le modifiche e i tentativi di modifica (cioè, operazioni fallite e conflitti di lock e deadlock).

Contatta il supporto IBSurgeon per ottenere maggiori informazioni: [email protected].

Come evitare i deadlock?

Ora devi identificare la soluzione migliore per la tua applicazione per evitare i deadlock - può essere un cambiamento dei parametri di transazione, o è possibile aggiungere un’elaborazione extra degli errori e ripetere l’operazione o eseguire controlli aggiuntivi a livello di business dell’applicazione.