分类： DB2/Informix
2013-07-23 14:41:10
deadlock_pb1.txt
在日常工作过程中，发现db2diag文件中有死锁报错信息。通过这次死锁的问题经历，主要想调查以下内容：
1、如何模拟死锁
2、死锁的问题记录会出现在哪里
3、使用db2cos监控死锁
4、使用事件监控器监控死锁
5、db2cos和事件监控器对于死锁监控的个人看法
首先，呈上自己在工作中发现的死锁信息。附件内容为本次死锁在db2diag文件中的报错信息，检查db2diag文件中的内容，摘取其核心部分如下：
2013-07-16-00.30.18.712028+120 E1235048710A1023 LEVEL: Warning
PID : 12386440 TID : 44071 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46241 APPID: 10.194.6.198.36325.130715160652
AUTHID : SAPPB1
EDUID : 44071 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1
MESSAGE : ADM5501I DB2 is performing lock escalation. The affected application
is named "disp+work", and is associated with the workload name
"SYSDEFAULTUSERWORKLOAD" and application ID
"10.194.6.198.36325.130715160652" at member "0". The total number of
locks currently held is "106", and the target number of locks to hold
is "53". The current statement being executed is "SELECT * FROM
"TSP01" WHERE "RQIDENT" = ? FOR UPDATE WITH RS USE AND KEEP
EXCLUSIVE LOCKS -- OPTLEVEL( 5 ) -- QUERY_DEGREE( 1 ) -- SYSTEM( PB1 ,
SAPPB1 )".
2013-07-16-00.30.18.864972+120 E1235049734A1061 LEVEL: Warning
PID : 12386440 TID : 50665 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46400 APPID: 10.194.6.198.37613.130715174327
AUTHID : SAPPB1
EDUID : 50665 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1
MESSAGE : ADM5501I DB2 is performing lock escalation. The affected application
is named "disp+work", and is associated with the workload name
"SYSDEFAULTUSERWORKLOAD" and application ID
"10.194.6.198.37613.130715174327" at member "0". The total number of
locks currently held is "54", and the target number of locks to hold
is "27". The current statement being executed is "SELECT "RQIDENT",
"RQLFDNR", "RQSUBID", "RQSAPTITLE", "RQDESC" FROM "TSP01P" WHERE
"RQSUBID" = ? -- OPTLEVEL( 5 ) -- QUERY_DEGREE( 1 ) -- LOCATION(
SAPLSPRR , 2130 ) -- SYSTEM( PB1 , SAPPB1 )".
……………………………………..
2013-07-16-00.30.26.457541+120 E1235055520A1025 LEVEL: Warning
PID : 12386440 TID : 52105 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-44130 APPID: 10.194.6.198.35851.130715152332
AUTHID : SAPPB1
EDUID : 52105 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1
MESSAGE : ADM5501I DB2 is performing lock escalation. The affected application
is named "disp+work", and is associated with the workload name
"SYSDEFAULTUSERWORKLOAD" and application ID
"10.194.6.198.35851.130715152332" at member "0". The total number of
locks currently held is "106", and the target number of locks to hold
is "53". The current statement being executed is "DELETE FROM "TBTCO"
WHERE "JOBCOUNT" = ? AND "JOBNAME" = ? -- OPTLEVEL( 5 ) --
QUERY_DEGREE( 1 ) -- LOCATION( RSBTCDEL2 , 1408 ) -- SYSTEM( PB1 ,
SAPPB1 )".
2013-07-16-00.32.34.291211+120 E1235056546A564 LEVEL: Error
PID : 12386440 TID : 27588 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46184 APPID: 10.194.6.198.36081.130715154403
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4
MESSAGE : ADM5503E The escalation of "92285" locks on table "SAPPB1
./BI0/TINSP_LOT" to lock intent "X" has failed. The SQLCODE is
"-911".
……………………………………………………
2013-07-16-00.32.34.961291+120 E1235063280A540 LEVEL: Error
PID : 12386440 TID : 50665 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46400 APPID: 10.194.6.198.37613.130715174327
AUTHID : SAPPB1
EDUID : 50665 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4
MESSAGE : ADM5503E The escalation of "2" locks on table "SAPPB1 .TSP01" to
lock intent "X" has failed. The SQLCODE is "-911".
2013-07-16-00.32.34.961360+120 E1235063821A540 LEVEL: Error
PID : 12386440 TID : 44071 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46241 APPID: 10.194.6.198.36325.130715160652
AUTHID : SAPPB1
EDUID : 44071 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4
MESSAGE : ADM5503E The escalation of "1" locks on table "SAPPB1 .TST03" to
lock intent "X" has failed. The SQLCODE is "-911".
2013-07-16-00.32.34.961763+120 I1235064362A557 LEVEL: Warning
PID : 12386440 TID : 50665 PROC : db2sysc 0
INSTANCE: db2pb1 NODE : 000 DB : PB1
APPHDL : 0-46400 APPID: 10.194.6.198.37613.130715174327
AUTHID : SAPPB1
EDUID : 50665 EDUNAME: db2agent (PB1) 0
FUNCTION: DB2 UDB, catcache support, sqlrlc_systables_fetch_from_disk, probe:60
MESSAGE : ZRC=0x80100002=-2146435070=SQLP_LDED "Dead lock detected"
DIA8002C A deadlock has occurred, rolling back transaction.
基本上，与-911相关的问题，都是锁的问题，且此信息明确的表示“Dead lock detected”，检测到死锁，回滚了事务。
由此可见，确实发生了死锁。和锁等待一样，死锁也是在并发环境下会遇到的锁的问题。与锁等待的区别在于，锁等待有可能会导致日志被hold，发生日志空间不足的问题；但是dead lock由于后台存在检查死锁的db2dlock线程（V9.5后，之前是进程）用来检查死锁并选择死锁中的一个application将其干掉，以解除死锁。因此，一旦发生了死锁，db2会自动解开死锁，死锁对于我们来说，只是db2diag中的一条报错或者警告信息。然而过多的死锁，必然会导致系统响应的滞后，需要尽量避免。而死锁大部分是由于应用设计的问题，所以，取得死锁的第一手信息提供给开发人员，能够帮助开发人员从根本上解决造成死锁的逻辑问题。于是，引出了我们的另一个关注点，那就是如何搜集死锁的信息。
在讨论如何搜集死锁的信息之前，我们还需要知道如何才能模拟死锁。
1、如何模拟死锁？
在9.7上模拟死锁的方法，参见文章《在db2 9.7版本下进行DB2死锁的模拟》，在此不再累述。
2、死锁的问题记录会出现在哪里？
在知道如何模拟死锁后，下一个需要解决的问题，就是，发生了死锁，其报错信息会记录在哪里？
其实，这也是困扰我的一个问题。如文章开篇所示，在db2diag中，是会记录死锁的问题信息（sqlcode -911， reason code 2），在生产环境中，我也确实从db2diag中找到了这样的信息（如附件所示）。但是，个人在进行模拟死锁时，虽然在模拟的CLP端爆出了检查到死锁，回滚事务（SQL0911N The current transaction has been rolled back because of a deadlock or timeout. Reason code "2". SQLSTATE=40001），但是，自己始终没有在db2diag.log中找到类似的信息。不清楚是因为自己的马虎还是根本就没有，所以，此处，暂时作为一个悬案…...初步结论是，相信死锁信息会被输出到db2diag中（有待继续验证）。所以，如果在db2diag中发现了大量的-911的waring或者error，可以考虑是存在死锁（或锁等）等锁的问题。
3、使用db2cos进行监控死锁
由于死锁的问题记录具体放在那里，自己并没有调查清楚，所以，无法提供给开发人员具体的参考信息（即使真的在db2diag中，里面提供的信息也是支离破碎的，参见开篇）。因此，为了协助开发人员进行问题的定位和解决，我们需要更详细的信息，使用db2cos回调脚本，就是其中的一种方法。
在《在db2 9.7版本下进行DB2死锁的模拟》一文中，已经提到了，使用db2cos回调脚本，可以用来进行死锁的信息的捕获（锁等信息的捕获也可以用此脚本）。当db2cos被调用时，db2diag中会有明显的记录说明db2cos被调用，信息如下：
2013-07-22-10.45.49.938442+120 I18677A467 LEVEL: Event
PID : 16121922 TID : 9255 PROC : db2sysc 0
INSTANCE: db2test NODE : 000 DB : SAMPLE
APPHDL : 0-168 APPID: *LOCAL.db2test.130722083625
AUTHID : DB2TEST
EDUID : 9255 EDUNAME: db2agent (SAMPLE) 0
FUNCTION: DB2 UDB, trace services, pdInvokeCalloutScript, probe:20
STOP : Completed invoking /home/db2test/sqllib/adm/db2cos
所以，使用db2cos进行第一时间的死锁信息的捕获，是可行的，其捕获的信息的输出位置是db2dump目录下的名为
首先，把sqllib/bin/db2cos这个文件拷贝到sqllib/adm/下面，然后，修改db2cos中的Locktimeout段，像这样
"LOCKTIMEOUT")
echo "Lock Timeout Caught" >> $logfile
if [ ! -n "$database" ]
then
db2pd -inst >> $logfile
else
db2pd -db $database -inst >> $logfile
fi
;;
把else那一段换成db2pd -db $database -locks -transaction -agents -application -dynamic，dbname写上数据库的名字；然后执行db2pdcfg -catch locktimeout
，然后，发生locktimeout的时候，去db2diag文件所在的目录，会生成一个文件（命名规则是
注意，一旦执行了db2pdcfg -catch locktimeout，以后每次的死锁都会被检测到并调用db2cos脚本进行处理，可以使用如下命令查看当前的开关状态：
$ db2pdcfg -catch status
Error Catch #1
Sqlcode: 0
ReasonCode: 0
ADMCode: 0
DiagText:
ZRC: -2146435070
ECF: 0
Component ID: 0
LockName: Not Set
LockType: Not Set
Current Count: 2
Max Count: 255
Bitmap: 0x4A1
Action: Error code catch flag enabled
Action: Execute /home/db2test/sqllib/adm/db2cos callout script
Action: Produce stack trace in db2diag.log
如果想关闭开关，使用db2pdcfg -catch clear。
$ db2pdcfg -catch clear
All error catch flag settings cleared.
$ db2pdcfg -catch status
All error catch flag settings cleared.
但是，通过这个脚本来看，实际上，只是在发生死锁的时候，执行了我们定义的db2pd的内容（db2pd -db $database -locks -transaction -agents -application -dynamic） ，如果我们愿意，修改脚本，完全可以在发生死锁的时候，让脚本给我输出一个“hello world”……换句话说，这个脚本，只是在发生死锁的时候，进行调用，执行你让他做的事情。
于是，就有新的问题了，我们知道，发生了死锁，也知道发生这些死锁的一些由db2pd输出的信息，如果说这些信息不够，或者说，想再从其他方面进行检测收集呢？
这个时候，就有另外一个工具来配合了，那就是死锁的事件监控器
4、使用事件监控器监控死锁
首先，创建死锁事件监控器（deadlock event monitor），并设置其生效：
$ mkdir deadlock_info
$ cd deadlock_info/
$ pwd
/home/db2test/deadlock_info
$ db2 "create event monitor dlockvm for deadlocks with details history write to file '/home/db2test/deadlock_'"
DB20000I The SQL command completed successfully.
$ db2 commit
DB20000I The SQL command completed successfully.
$ db2 set event monitor dlockvm state=1
DB20000I The SQL command completed successfully.
其次，模拟死锁现象：
CLP1：
$ db2 +c "insert into t21 values('bbb')"
DB20000I The SQL command completed successfully.
CLP2：
$ db2 +c "insert into t11 values('aaa')"
DB20000I The SQL command completed successfully.
CLP1:
$ db2 +c "select * from t11"
COL1
----------
0 record(s) selected.
CLP2：
$ db2 +c "select * from t21"
SQL0911N The current transaction has been rolled back because of a deadlock
or timeout. Reason code "2". SQLSTATE=40001
死锁现象出现。
再次，关闭死锁事件监控器，并将结果输出到一个文本文件中：
$ db2 flush event monitor dlockvm
DB20000I The SQL command completed successfully.
$ db2 set event monitor dlockvm state=0
DB20000I The SQL command completed successfully.
$ pwd
/home/db2test/deadlock_info
$ ls
00000000.evt db2event.ctl
$
$ db2evmon -path /home/db2test/deadlock_info > deadlock.txt
Reading /home/db2test/deadlock_info/00000000.evt ...
$ ls
00000000.evt db2event.ctl deadlock.txt
最后，进行死锁结果的分析：
deadlock.txt
这个文件（deadlock.txt）的内容，可丰富了……具体的每段的意思，可以参考信息中心。
5、db2cos和事件监控器对于死锁监控的个人看法
由于死锁本身会被db2dlock检测并干掉，所以，对于我们来说，死锁只是一个瞬时的现象，能够做到的是，知道发生了死锁，并抓到相应的信息。因此，从这个角度来看，个人比较倾向于这样处理：
首先，查看db2diag中，是不是有-911的报错；
其次，使用快照，抓取数据库快照中与锁相关的信息，像上例，从快照中抓取可以看到如下信息：
$ db2 get snapshot for database on sample | grep -i lock
Locks held currently = 0
Lock waits = 2
Time database waited on locks (ms) = 13683
Lock list memory in use (Bytes) = 25344
Deadlocks detected = 1
Lock escalations = 0
Exclusive lock escalations = 0
Agents currently waiting on locks = 0
Lock Timeouts = 0
Block IOs = Not Collected
Pages from block IOs = Not Collected
Internal rollbacks due to deadlock = 1
Number of MDC table blocks pending cleanup = 0
Memory Pool Type = Lock Manager Heap
如果有很多的死锁或锁相关的内容，可以先使用db2cos
再次，使用db2cos，个人认为，这个工具的开销比事件监控器要小，所以，优先采用这种做法进行信息的收集会比较好一些，如果收集的信息还不够全面，再使用事件监控器；
最后，如果感觉db2pd收集的信息不够，那就用死锁事件监控器吧。
结论：进行锁的问题的诊断，自己没有参与很多，所以，只是将可能的信息收集方法和自己遇到类似问题的处理思路记录了下来。如果有幸参与类似工作，再进行验证和详细记录。
