联系方式
IBSurgeon
此页面为机器翻译。请阅读英文原文。 English

如何在Firebird中跟踪死锁

Alexey Kovyazin，2019年5月8日，(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个主键列的表。

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>

我们在会话1中启动了UPDATE但未提交。

在会话2中，UPDATE“挂起”了–它等待并发事务结束，当我们提交会话1中的UPDATE时，会话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]。

如何避免死锁？

现在您需要为您的应用程序确定最佳解决方案以避免死锁–可以是更改事务参数，或者可以添加额外的错误处理并重试操作，或者在应用程序的业务层面执行额外的检查。