Как искать причины deadlock в Firebird

Алексей Ковязин, 08.05.2019, (c) IBSurgeon, iBase.ru

Конфликты обновления (часто называемые "дэдлоками" (deadlocks)) возникают в приложениях на Firebird при интенсивных конкурентных обновлениях данных.

В статье о конфликтах обновлений перечислено три типа конфликтов, содержащих слово "deadlock".
(есть еще старая статья "Что такое deadlock и как с ним бороться")

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

Все три типа этих конфликтов в общем являются результатами конфликта обновлений, когда 2 запроса пытаются обновить одну и ту же запись.
Это запросы: UPDATE, DELETE, SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Поймать запрос, который выдал ошибку, относительно легко - потому что он и получит сообщение об ошибке. В этом случае достаточно обрамить подозрительное место в try… catch и сохранить в лог параметры, при которых произошла ошибка.

Однако, в этом случае тяжело поймать конкурирующий запрос, который произвел обновление успешно.

Чтобы облегчить разработчикам поиск конкурента, Firebird помещает в сообщение об ошибке номер конкурирующей транзакции. Вместе с трассировкой это дает возможность найти обе конкурирующие операции.

Давайте по шагам сделаем это.

Для начала, нам надо сконфигурировать трассировку. Создайте текстовый файл (в нашем случае это C:\Temp\mytrace.conf) со следующим содержимым:

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

}
Приведенная выше конфигурация будет трассировать все базы данных, с которыми работают на сервере. Если вам нужна конкретная база данных, тогда лучше явно ее указать: 
Database=mydatabase.fdb
{
  enabled = true
…
}
Рассмотрим подробнее другие параметры конфигурации трассировки:

Что отслеживать

include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"
Здесь мы отслеживаем только те операторы, которые могут привести к дэдлокам. Обычные select исключаем, потому что иначе лог трассировки получится слишком большим, да и select (без with lock) не может привести к блокировкам (уровень изолированности read committed no record version здесь не рассматриваем).

Если нас интересуют дэдлоки, возникающие только на конкретных таблицах, мы можем еще уменьшить вывод трассировки, указав явно в фильтре имя такой таблицы:

include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%WITH lock%)|(UPDATE OR INSERT INTO T1%)"
А что если обновления и удаления производятся хранимыми процедурами или триггерами? Да, это усложняет задачу - надо будет явно добавить в фильтр имена "проблемных" объектов: 
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

Логирование ошибок

Теперь нам нужно указать, что мы будем логировать - только дэдлоки: 
log_errors = true
include_gds_codes="deadlock"
Замечание: параметр include_gds_codes появился только в Firebird 3.0.2, поэтому на 2.5, 3.0.0 или 3.0.1 невозможно фильтровать ошибки, выводиться будут все.

Пример

Для демонстрации процесса давайте подготовим тестовую базу данных – для упрощения будет 1 таблица с 1 столбцом первичного ключа. 
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;
После этого стартуем сессию трассировки: 
fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\mytrace.conf" -user SYSDBA -pass masterkey
В этом случае fbtracemgr будет выводить лог на экран. В промышленной системе, разумеется, лог лучше выводить в файл, для последующего анализа.

После успешного старта fbtracemgr выведет информацию:

Trace session ID 4 started
Давайте теперь запустим 2 isql, и попытаемся имитировать конфликт обновления. В таблице ниже по столбцу на каждый isql. А строки представляют действия в конкретном isql и очередность действий.
Time isql session 1 isql session 2
T1 
isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb
Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA
SQL> set transaction wait;
Commit current transaction (y/n)?y
Committing.
SQL> select current_transaction from rdb$database;

  CURRENT_TRANSACTION
=====================
                   15

SQL> select * from t1;

          I1
============
           2

SQL>
 
T2   
isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb
Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA
SQL> set transaction wait;
Commit current transaction (y/n)?y
Committing.
SQL> select current_transaction from rdb$database;

  CURRENT_TRANSACTION
=====================
                   20
SQL> select * from t1;

          I1
============
           2

SQL>
Вначале мы видим, что стартовали две транзакции - #15 и #20. Теперь попробуем одновременно обновить одну и ту же запись из двух isql:
     
T3 
SQL> UPDATE T1 SET i1=5 where i1=2;
 
T4   
SQL> UPDATE T1 SET i1=100 where i1=2;
T5 
SQL> commit;
SQL>

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

Стартуем UPDATE в сессии 1, и не завершаем транзакцию.
В сессии 2, UPDATE «зависает» - ждет завершения конкурирующей транзакции, и в результате, раз мы подтвердили UPDATE в сессии 1, сессия 2 получает ошибку:

Statement failed, SQLSTATE = 40001
deadlock
-update conflicts with concurrent update
-concurrent transaction number is 15
SQL>
В результате видим типичный конфликт обновления с транзакцией wait.

Посмотрим теперь на лог трассировки, чтобы убедиться в регистрации конфликта.

В этом случае лог трассировки очень короткий, но в промышленной системе он может быть гораздо больше. Но принцип поиска дэдлоков тот же самый. 
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
Как видите, у нас в логе зарегистрированы оба обновления – успешное и с ошибкой, и сообщение об ошибке.

Теперь, как это анализировать:
В сообщении об ошибке находим номер конкурирующей транзакции:

 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
Рядом с сообщением об ошибке (обычно чуть выше) мы видим проблемный запрос: 
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)
Обратите внимание, что длительность выполнения большая (~40 секунд) – столько UPDATE ждал завершения конкурирующей транзакции.

И, наконец, ищем выше успешный UPDATE в конкурирующей транзакции : найдите TRA_NNN, где NNN это номер транзакции. В нашем случае это TRA_15:

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)
Нашли - и запрос с ошибкой, и успешный конкурирующий.

Как избежать дэдлоков ?

Теперь вам нужно самостоятельно найти решение для исключения дэдлоков в ваших приложениях - это может быть изменение параметров транзакции, или добавление дополнительной обработки ошибок для повторения операции, или дополнительные проверки на уровне бизнес-логики приложения, или вообще изменение бизнес-логики.

 

Подпишитесь на новости Firebird в России

Подписаться