Kontakty
IBSurgeon
Ta strona została przetłumaczona maszynowo. Przeczytaj oryginał angielski. English

Jak śledzić zakleszczenia w Firebird

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

Konflikty aktualizacji (często nazywane „zakleszczeniami”) występują w aplikacjach Firebird, które wykonują intensywne równoczesne aktualizacje danych.

Jak widać z artykułu « Transakcje w Firebirdzie», istnieją 3 typy błędów zawierających słowo kluczowe „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

Wszystkie 3 typy konfliktów aktualizacji mają wspólną cechę: konflikt aktualizacji jest zwykle wynikiem 2 operacji modyfikacji, które próbują zmodyfikować ten sam rekord.

Możliwe opcje to: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Stosunkowo łatwo jest śledzić operację „ofiary”, która otrzymuje komunikat o błędzie - wystarczy umieścić ją w try… catch i zalogować parametry użyte w zapytaniu, które kończy się błędem.

Jednak przy takim podejściu trudno jest śledzić „zwycięzcę” - czyli równoczesną transakcję, w której aktualizacja została wykonana pomyślnie, bez błędu.

Aby pomóc programistom w badaniu konfliktów aktualizacji, Firebird umieszcza w komunikatach o błędach odniesienie do równoczesnej transakcji - czyli transakcji, w której równoczesna aktualizacja nie została jeszcze zatwierdzona. Wraz z Trace API daje nam to możliwość śledzenia obu konfliktujących operacji.

Rozważmy praktyczne kroki, jak to zrobić.

Najpierw musimy skonfigurować śledzenie. W tym celu utwórz plik tekstowy (w naszym przypadku C:\Temp\mytrace.conf) o następującej zawartości:

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

}

Powyższy plik konfiguracyjny włącza śledzenie dla wszystkich baz danych, więc jeśli masz więcej niż 1 aktywną bazę danych, lepiej podać nazwę bazy danych w pliku konfiguracyjnym, tj.:

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

Przeanalizujmy najważniejsze parametry w pliku konfiguracyjnym:

Parametr include filter

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

Oznacza to, że chcemy śledzić tylko instrukcje UPDATE i DELETE oraz ignorować selekcje. Konieczne jest odfiltrowanie jak największej liczby instrukcji, ponieważ w systemie produkcyjnym pod dużym obciążeniem ilość rekordów w logu tekstowym może być zbyt duża do analizy.

Zazwyczaj wiemy, która tabela uczestniczy w konflikcie aktualizacji; dobrym pomysłem będzie umieszczenie jej w filtrze, aby zmniejszyć liczbę aktualizacji do analizy:

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

Co jeśli aktualizacje i usunięcia są wykonywane przez procedury składowane? Cóż, to utrudnia cały proces: dodaj do filtra wszystkie procedury składowane, które mogą być zaangażowane w równoczesne aktualizacje, a także włącz logowanie 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 logowania błędów

Następnie musimy określić logowanie błędów i ograniczyć je do zakleszczeń.

Code 
log_errors = true
include_gds_codes="deadlock"

Uwaga: parametr include_gds_codes pojawił się dopiero w Firebird 3.0.2, więc jeśli używasz 2.5 lub 3.0.0 lub 3.0.1, nie jest możliwe filtrowanie tylko błędów zakleszczenia, więc wszystkie błędy będą zapisywane do logu.

Demonstracja

Aby zademonstrować cały proces, przygotujmy testową bazę danych - dla uproszczenia będzie 1 tabela z 1 kolumną klucza podstawowego.

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;

Następnie musimy uruchomić sesję śledzenia:

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

W tym przypadku fbtracemgr wypisuje log na ekran, ale w produkcji musimy przekierować go do pliku, oczywiście.

Po pomyślnym uruchomieniu fbtracemgr wypisuje coś takiego:

Code 
Trace session ID 4 started

Następnie uruchommy 2 sesje isql i spróbujmy zasymulować konflikt aktualizacji. W poniższej tabeli mamy 2 kolumny dla 2 sesji isql. Każdy wiersz reprezentuje moment w czasie, w którym wykonano polecenia.
Czas sesja isql 1 sesja 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>
Tak więc w punkcie startowym widzimy, że uruchomione są 2 transakcje, #15 i #20. Następnie spróbujmy wykonać równoczesną aktualizację tego samego rekordu:
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>

Rozpoczęliśmy UPDATE w sesji 1, ale go nie zatwierdziliśmy.

W sesji 2 UPDATE „zawisł” - czekał na zakończenie równoczesnej transakcji, a gdy zatwierdziliśmy UPDATE w sesji 1, sesja 2 otrzymała błąd:

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

Mamy więc typową sytuację w przypadku konfliktu aktualizacji z transakcją oczekującą.

Przeanalizujmy log śledzenia, aby znaleźć dowody konfliktu aktualizacji.

W tym przypadku log śledzenia jest bardzo krótki, ale w przypadku systemu produkcyjnego może być znacznie dłuższy, ale podejście do znajdowania zakleszczeń jest takie samo.

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 widać, mamy w logu rekordy dotyczące obu aktualizacji - udanej i nieudanej, oraz komunikat o błędzie dotyczący zakleszczenia.

Rozważmy, jak analizować log:

W komunikacie o błędzie znajdźmy identyfikator transakcji:

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

W pobliżu rekordu o błędzie (zwykle tuż nad nim) zobaczysz nieudaną instrukcję:

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)

Zauważ, że czas wykonania jest ogromny (~40 sekund) - wskazuje to czas, w którym operacja oczekiwała na wynik równoczesnej transakcji.

I wreszcie, poszukaj numeru transakcji z udaną operacją UPDATE: w tym celu znajdź TRA_NNN, gdzie NNN to numer transakcji. W naszym przypadku będzie to 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)

I to wszystko - znaleźliśmy obie strony konfliktu aktualizacji - udaną i nieudaną.

Narzędzia do identyfikacji zakleszczeń

Jak widać, identyfikacja źródłowej przyczyny konfliktu blokad/zakleszczenia może być dość trudna: ponieważ konflikt zawsze ma 2 strony, a jedna strona „wygrywa” (kończy się bez komunikatów o błędach), zidentyfikowanie zwycięzcy może być trudne. Na przykład konflikt może wystąpić wewnątrz EXECUTE STATEMENT, w zagnieżdżonej procedurze składowanej, wewnątrz wyzwalacza lub może być kombinacją tych wszystkich rzeczy.

W celu identyfikacji zakleszczeń IBSurgeon opracował narzędzie „Deadlock Analyzer”, które analizuje log śledzenia i tworzy łatwe do zrozumienia diagramy ze szczegółami wywołań, które doprowadziły do zakleszczeń. To narzędzie jest dostępne w ramach Enterprise Subscription (ma wersję próbną) - zarejestruj się na cc.ib-aid.com.

Ponadto HQbird wprowadza rozszerzoną wersję wtyczki fbtrace, którą można skonfigurować tak, aby zapisywała tylko zmiany i próby zmian (tj. nieudane operacje oraz konflikty blokad i zakleszczenia).

Skontaktuj się z pomocą techniczną IBSurgeon, aby uzyskać więcej informacji: [email protected].

Jak unikać zakleszczeń?

Teraz musisz zidentyfikować najlepsze rozwiązanie dla swojej aplikacji, aby uniknąć zakleszczeń - może to być zmiana parametrów transakcji, dodanie dodatkowego przetwarzania błędów i powtórzenie operacji lub wykonanie dodatkowych kontroli na poziomie biznesowym aplikacji.