Kontakty
IBSurgeon
Tato stránka byla strojově přeložena. Přečtěte si anglický originál. English

Jak sledovat deadlocky ve Firebirdu

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

Aktualizační konflikty (často nazývané „deadlocky“) se vyskytují v aplikacích Firebird, které provádějí intenzivní souběžné aktualizace dat.

Jak můžete vidět z článku « Transakce ve Firebirdu», existují 3 typy chyb, které obsahují klíčové slovo „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

Všechny 3 typy aktualizačních konfliktů mají společné to, že aktualizační konflikt je obvykle výsledkem 2 modifikačních operací, které se pokoušejí upravit stejný záznam.

Možné varianty jsou následující: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Je poměrně snadné sledovat operaci „oběť“, která obdrží chybovou zprávu - stačí ji umístit do try… catch a zaznamenat parametry použité v dotazu, který na chybě selže.

S tímto přístupem je však obtížné sledovat „vítěze“ - tj. souběžnou transakci, kde byla aktualizace provedena úspěšně, bez chyby.

Aby pomohl vývojářům vyšetřit aktualizační konflikty, Firebird vkládá do chybových zpráv odkaz na souběžnou transakci - tj. transakci, kde souběžná aktualizace ještě není potvrzena. Spolu s Trace API nám to dává možnost sledovat obě konfliktní operace.

Podívejme se na praktické kroky, jak to provést.

Nejprve musíme nakonfigurovat trasování. Za tímto účelem vytvořte textový soubor (v našem případě C:\Temp\mytrace.conf) s následujícím obsahem:

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

}

Výše uvedený konfigurační soubor povoluje trasování pro všechny databáze, takže pokud máte více než 1 aktivní databázi, je lepší zadat název databáze v konfiguračním souboru, tj.:

Code 
Database=mydatabase.fdb
{
  enabled = true
…
}

Podívejme se na nejdůležitější parametry v konfiguračním souboru:

Parametr include filter

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

To znamená, že chceme sledovat pouze příkazy UPDATE a DELETE a ignorovat selecty. Je nutné odfiltrovat co nejvíce příkazů, protože v produkčním systému při vysokém zatížení může být množství záznamů v textovém logu příliš velké na analýzu.

Obvykle víme, která tabulka se účastní aktualizačního konfliktu, dobrý nápad bude ji vložit do filtru, aby se snížil počet aktualizací k analýze:

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

Co když jsou aktualizace a mazání prováděny uloženými procedurami? No, to celý proces ztěžuje: přidejte do filtru všechny uložené procedury, které mohou být zapojeny do souběžných aktualizací, a také povolte protokolování procedur:

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

Parametry protokolování chyb

Poté musíme zadat protokolování chyb a omezit jej na deadlocky.

Code 
log_errors = true
include_gds_codes="deadlock"

Poznámka: parametr include_gds_codes se objevil až ve Firebirdu 3.0.2, takže pokud používáte 2.5 nebo 3.0.0 nebo 3.0.1, není možné filtrovat pouze chyby deadlock, takže všechny chyby budou vytištěny do logu.

Demonstrace

Pro demonstraci celého procesu připravíme testovací databázi - pro jednoduchost bude 1 tabulka s 1 primárním sloupcem.

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;

Poté musíme spustit trasovací relaci:

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

V tomto případě fbtracemgr tiskne log na obrazovku, ale v produkci jej samozřejmě musíme přesměrovat do souboru.

Po úspěšném spuštění fbtracemgr vytiskne něco jako:

Code 
Trace session ID 4 started

Poté spustíme 2 isql relace a pokusíme se simulovat aktualizační konflikt. V níže uvedené tabulce máme 2 sloupce pro 2 isql relace. Každý řádek představuje okamžik v čase, kdy byly příkazy provedeny.
Čas isql relace 1 isql relace 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>
Takže na počátečním bodě vidíme, že jsou spuštěny 2 transakce, #15 a #20. Poté zkusme provést souběžnou aktualizaci stejného záznamu:
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>

Spustili jsme UPDATE v relaci 1, ale nepotvrdili jsme jej.

V relaci 2 UPDATE „visel“ - čekal na konec souběžné transakce, a když jsme potvrdili UPDATE v relaci 1, relace 2 obdržela chybu:

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

Takže máme typickou situaci v případě aktualizačního konfliktu s čekající transakcí.

Podívejme se na trasovací log, abychom našli důkazy aktualizačního konfliktu.

V tomto případě je trasovací log velmi krátký, ale v případě produkčního systému může být mnohem delší, ale přístup k nalezení deadlocků je stejný.

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

Jak vidíte, máme v logu záznamy o obou aktualizacích - úspěšné i neúspěšné, a chybovou zprávu o deadlocku.

Podívejme se, jak analyzovat log:

V chybové zprávě najdeme identifikátor transakce:

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

Vedle záznamu o chybě (obvykle přímo nad ním) uvidíte neúspěšný příkaz:

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)

Všimněte si, že doba provádění je obrovská (~40 sekund) - to indikuje čas, kdy operace čekala na výsledek souběžné transakce.

A nakonec vyhledejte číslo transakce s úspěšnou operací UPDATE: za tímto účelem najděte TRA_NNN, kde NNN je číslo transakce. V našem případě to bude 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)

Takže to je ono - našli jsme obě strany aktualizačního konfliktu - úspěšnou i neúspěšnou.

Nástroje pro identifikaci deadlocků

Jak vidíte, může být docela obtížné identifikovat hlavní zdroj konfliktu zámků/deadlocku: protože konflikt má vždy 2 strany a jedna strana „vyhrává“ (dokončí bez chybových zpráv), může být záludné identifikovat vítěze. Například konflikt může nastat uvnitř EXECUTE STATEMENT, nebo v vnořené uložené proceduře, nebo uvnitř triggeru, nebo to může být kombinace všech těchto věcí.

Aby pomohl identifikovat deadlocky, IBSurgeon vyvinul nástroj „Deadlock Analyzer“, který analyzuje trasovací log a vytváří snadno srozumitelné diagramy s podrobnostmi o voláních, která vedla k deadlockům. Tento nástroj je k dispozici jako součást Enterprise Subscription (má zkušební verzi) - zaregistrujte se na cc.ib-aid.com.

Také HQbird představuje rozšířenou verzi pluginu fbtrace, který lze nakonfigurovat tak, aby ukládal pouze změny a pokusy o změny (tj. neúspěšné operace a konflikty zámků a deadlocky).

Kontaktujte podporu IBSurgeon pro více informací: [email protected].

Jak se vyhnout deadlockům?

Nyní musíte identifikovat nejlepší řešení pro vaši aplikaci, abyste se vyhnuli deadlockům - může to být změna parametrů transakce, nebo je možné přidat dodatečné zpracování chyb a opakovat operaci nebo provést dodatečné kontroly na obchodní úrovni aplikace.