Как отслеживать взаимоблокировки в Firebird

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

Конфликты обновлений (часто называемые «взаимоблокировками») возникают в приложениях Firebird, которые выполняют интенсивные параллельные обновления данных.

Как видно из статьи « Транзакции в Firebird», существует 3 типа ошибок, содержащих ключевое слово «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

Все 3 типа конфликтов обновлений имеют общую черту: конфликт обновлений обычно является результатом двух операций модификации, которые пытаются изменить одну и ту же запись.

Возможные варианты: UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.

Относительно легко отследить операцию-«жертву», которая получает сообщение об ошибке - просто поместите её в try… catch и запишите параметры, используемые в запросе, который завершается с ошибкой.

Однако при таком подходе сложно отследить «победителя» - то есть параллельную транзакцию, в которой обновление было выполнено успешно, без ошибки.

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

Рассмотрим практические шаги, как это сделать.

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

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

}

Приведённый выше файл конфигурации включает трассировку для всех баз данных, поэтому если у вас более одной активной базы данных, лучше указать имя базы данных в файле конфигурации, например:

Code

Database=mydatabase.fdb
{
  enabled = true
…
}

Рассмотрим наиболее важные параметры в файле конфигурации:

Параметр include filter

Code

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

Это означает, что мы хотим отслеживать только операторы UPDATE и DELETE и игнорировать SELECT. Необходимо отфильтровать как можно больше операторов, потому что в производственной системе при высокой нагрузке количество записей в текстовом журнале может быть слишком большим для анализа.

Обычно мы знаем, какая таблица участвует в конфликте обновлений, поэтому хорошей идеей будет добавить её в фильтр, чтобы уменьшить количество обновлений для анализа:

Code

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

Что если обновления и удаления выполняются хранимыми процедурами? Это усложняет весь процесс: добавьте в фильтр все хранимые процедуры, которые могут участвовать в параллельных обновлениях, а также включите журналирование процедур:

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

Параметры журналирования ошибок

Затем нам нужно указать журналирование ошибок и ограничить его только взаимоблокировками.

Code

log_errors = true
include_gds_codes="deadlock"

Обратите внимание: параметр include_gds_codes появился только в Firebird 3.0.2, поэтому если вы используете 2.5, 3.0.0 или 3.0.1, невозможно отфильтровать только ошибки взаимоблокировок, и все ошибки будут записаны в журнал.

Демонстрация

Чтобы продемонстрировать весь процесс, подготовим тестовую базу данных - для простоты в ней будет 1 таблица с 1 первичным столбцом.

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;

После этого нам нужно запустить сеанс трассировки:

Code

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

В этом случае fbtracemgr выводит журнал на экран, но в производственной среде его, конечно, нужно перенаправить в файл.

После успешного запуска fbtracemgr выводит что-то вроде этого:

Code

Trace session ID 4 started

Затем запустим 2 сеанса isql и попробуем смоделировать конфликт обновлений. В таблице ниже у нас 2 столбца для 2 сеансов isql. Каждая строка представляет момент времени, когда были выполнены команды.


Время	сеанс isql 1	сеанс 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>`
Итак, в начальной точке мы видим, что запущены 2 транзакции, #15 и #20. Затем попробуем выполнить параллельное обновление одной и той же записи:

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

Мы запустили UPDATE в сеансе 1, но не зафиксировали его.

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

Code

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

Итак, у нас типичная ситуация конфликта обновлений с ожидающей транзакцией.

Рассмотрим журнал трассировки, чтобы найти доказательства конфликта обновлений.

В этом случае журнал трассировки очень короткий, но в случае производственной системы он может быть намного длиннее, однако подход к поиску взаимоблокировок тот же.

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

Как видите, в журнале есть записи об обоих обновлениях - успешном и неудачном, а также сообщение об ошибке взаимоблокировки.

Рассмотрим, как анализировать журнал:

В сообщении об ошибке найдем идентификатор транзакции:

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

Рядом с записью об ошибке (обычно сразу над ней) вы увидите неудачный оператор:

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)

Обратите внимание, что время выполнения огромное (~40 секунд) - это указывает на время, в течение которого операция ожидала результата параллельной транзакции.

И, наконец, найдите номер транзакции с успешной операцией UPDATE: для этого найдите TRA_NNN, где NNN - номер транзакции. В нашем случае это будет 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)

Итак, вот и всё - мы нашли обе стороны конфликта обновления - успешную и неудачную.

Инструменты для выявления взаимоблокировок

Как видите, может быть довольно сложно определить корневую причину конфликта блокировок/взаимоблокировки: поскольку конфликт всегда имеет две стороны, и одна сторона «выигрывает» (завершается без сообщений об ошибках), может быть непросто определить победителя. Например, конфликт может произойти внутри EXECUTE STATEMENT, во вложенной хранимой процедуре, внутри триггера или быть комбинацией всех этих факторов.

Для выявления взаимоблокировок компания IBSurgeon разработала инструмент «Deadlock Analyzer», который анализирует журнал трассировки и создает понятные диаграммы с деталями вызовов, приведших к взаимоблокировкам. Этот инструмент доступен в рамках Enterprise Subscription (есть пробная версия) - зарегистрируйтесь на cc.ib-aid.com.

Кроме того, HQbird представляет расширенную версию плагина fbtrace, которую можно настроить на сохранение только изменений и попыток изменений (т.е. неудачных операций, конфликтов блокировок и взаимоблокировок).

Свяжитесь со службой поддержки IBSurgeon, чтобы получить дополнительную информацию: [email protected].

Как избежать взаимоблокировок?

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