Contacten
IBSurgeon
Deze pagina is automatisch vertaald. Lees het Engelse origineel. English

Hoe deadlocks in Firebird te volgen

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

Updateconflicten (vaak “deadlocks” genoemd) komen voor in Firebird-toepassingen die intensieve gelijktijdige updates van gegevens uitvoeren.

Zoals u kunt zien in het artikel « Transacties in Firebird», zijn er 3 soorten fouten die het trefwoord “deadlock” bevatten:

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

Alle 3 soorten updateconflicten hebben gemeen dat het updateconflict meestal het resultaat is van 2 wijzigingsbewerkingen die proberen hetzelfde record te wijzigen.

De mogelijke opties zijn de volgende: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Het is relatief eenvoudig om de “slachtoffer”-bewerking te volgen, die het foutbericht ontvangt - plaats het gewoon in try… catch en log de parameters die worden gebruikt in de query die op de fout breekt.

Met deze aanpak is het echter moeilijk om de “winnaar” te volgen - d.w.z. de gelijktijdige transactie waarin de update succesvol is uitgevoerd, zonder fout.

Om ontwikkelaars te helpen bij het onderzoeken van updateconflicten, plaatst Firebird in foutberichten de verwijzing naar de gelijktijdige transactie - d.w.z. de transactie waarin de gelijktijdige update nog niet is vastgelegd. Samen met de Trace API geeft dit ons de mogelijkheid om beide conflicterende bewerkingen te volgen.

Laten we de praktische stappen bekijken om dit te doen.

Eerst moeten we tracing configureren. Maak hiervoor een tekstbestand (in ons geval C:\Temp\mytrace.conf) met de volgende inhoud:

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

}

Het bovenstaande configuratiebestand schakelt tracing in voor alle databases, dus als u meer dan 1 actieve database heeft, kunt u beter de naam van de database in het configuratiebestand specificeren, d.w.z.:

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

Laten we de belangrijkste parameters in het configuratiebestand bekijken:

Include filter parameter

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

Dit betekent dat we alleen UPDATE- en DELETE-instructies willen volgen en selects negeren. Het is noodzakelijk om zoveel mogelijk instructies uit te filteren, omdat in een productiesysteem onder hoge belasting het aantal records in het tekstlogboek te groot kan zijn om te analyseren.

Meestal weten we welke tabel deelneemt aan het updateconflict; het is een goed idee om deze in het filter op te nemen om het aantal updates te verminderen dat moet worden geanalyseerd:

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

Wat als updates en deletes worden uitgevoerd door opgeslagen procedures? Nou, dat maakt het hele proces moeilijker: voeg aan het filter alle opgeslagen procedures toe die betrokken kunnen zijn bij gelijktijdige updates, en schakel ook logging van procedures in:

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

Foutlogparameters

Vervolgens moeten we de foutlogging specificeren en beperken tot deadlocks.

Code 
log_errors = true
include_gds_codes="deadlock"

Houd er rekening mee: de parameter include_gds_codes is pas verschenen in Firebird 3.0.2, dus als u 2.5 of 3.0.0 of 3.0.1 gebruikt, is het niet mogelijk om alleen deadlock-fouten te filteren, dus alle fouten worden naar het logboek afgedrukt.

Demonstratie

Om het hele proces te demonstreren, bereiden we de testdatabase voor - voor de eenvoud is er 1 tabel met 1 primaire kolom.

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;

Daarna moeten we de tracesessie starten:

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

In dit geval drukt fbtracemgr het logboek af op het scherm, maar in productie moeten we het natuurlijk naar een bestand omleiden.

Na een succesvolle start drukt fbtracemgr iets af als:

Code 
Trace session ID 4 started

Vervolgens starten we 2 isql-sessies en proberen we het updateconflict te simuleren. In de onderstaande tabel hebben we 2 kolommen voor 2 isql-sessies. Elke rij vertegenwoordigt een moment in de tijd waarop de opdrachten werden uitgevoerd.
Tijd isql-sessie 1 isql-sessie 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>
Dus op het startpunt zien we dat er 2 transacties zijn gestart, #15 en #20. Laten we vervolgens proberen de gelijktijdige update van hetzelfde record uit te voeren:
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>

We hebben UPDATE in sessie 1 gestart maar niet vastgelegd.

In sessie 2 “hing” UPDATE - het wachtte op het einde van de gelijktijdige transactie, en toen we UPDATE in sessie 1 vastlegden, ontving sessie 2 de fout:

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

Dus we hebben een typische situatie in het geval van een updateconflict met een wachtende transactie.

Laten we het tracelogboek bekijken om het bewijs van het updateconflict te vinden.

In dit geval is het tracelogboek erg kort, maar in het geval van een productiesysteem kan het veel langer zijn, maar de aanpak om deadlocks te vinden is hetzelfde.

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

Zoals u kunt zien, hebben we records in het logboek over beide updates - succesvol en mislukt, en een foutmelding over deadlock.

Laten we bekijken hoe we het logboek moeten analyseren:

In het foutbericht lokaliseren we de identificatie van de transactie:

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

In de buurt van het record over de fout (meestal er direct boven), ziet u de mislukte instructie:

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)

Merk op dat de uitvoeringstijd enorm is (~40 seconden) - dit geeft de tijd aan waarin de bewerking wachtte op het resultaat van de gelijktijdige transactie.

En tot slot zoeken we naar het transactienummer met de succesvolle UPDATE-bewerking: zoek hiervoor naar TRA_NNN, waarbij NNN het transactienummer is. In ons geval is dat 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)

Dus dit is het - we hebben beide partijen van het updateconflict gevonden - de succesvolle en de mislukte.

Hulpmiddelen om deadlocks te identificeren

Zoals u kunt zien, kan het vrij moeilijk zijn om de oorspronkelijke bron van een lockconflict/deadlock te identificeren: aangezien het conflict altijd 2 kanten heeft, en één kant “wint” (zonder foutmeldingen voltooit), kan het lastig zijn om de winnaar te identificeren. Een conflict kan bijvoorbeeld optreden binnen EXECUTE STATEMENT, of in een geneste opgeslagen procedure, of binnen een trigger, of het kan een combinatie van al deze dingen zijn.

Om deadlocks te identificeren, heeft IBSurgeon de “Deadlock Analyzer”-tool ontwikkeld, die tracelogboeken analyseert en gemakkelijk te begrijpen diagrammen maakt met details van aanroepen die tot deadlocks hebben geleid. Deze tool is beschikbaar als onderdeel van Enterprise Subscription (het heeft een proefversie) - registreer op cc.ib-aid.com.

HQbird introduceert ook een uitgebreide versie van de fbtrace-plugin, die kan worden geconfigureerd om alleen wijzigingen en pogingen tot wijzigingen op te slaan (d.w.z. mislukte bewerkingen en lockconflicten en deadlocks).

Neem contact op met IBSurgeon-ondersteuning voor meer informatie hierover: [email protected].

Hoe deadlocks te voorkomen?

Nu moet u de beste oplossing voor uw toepassing identificeren om deadlocks te voorkomen - dit kan een wijziging van de transactieparameters zijn, of het is mogelijk om extra foutverwerking toe te voegen en de bewerking te herhalen of aanvullende controles uit te voeren op het bedrijfsniveau van de toepassing.