db2死锁、锁超时的案例分析

问题描述：在一个运行于DB2上的OLTP系统中，应用程序每两个小时挂起一次。挂起持续的时间每次长达2～3分钟甚至更多。在挂起期间，所有的INSERT、UPDATE和DELETE操作都无响应，但是一些查询操作可以执行。

运行环境：DB2 V9.1，操作系统 AIX 5.3。

最初怀疑问题是由锁定等待引起的，但是当把LOCKTIMEOUT设置为10秒之后，此挂起现象依然继续发生。挂起发生后，应用程序也不会因为锁超 时而被回滚。同时，每次挂起发生的频率为非常准确的两小时。使用GET SNAPSHOT和db2pd观察挂起发生期间锁的状况，也没有发现异常。但是可以注意到很多应用在挂起期间都处于"Commit Active"状态：

Application status =  Commit  Active

在调整了缓冲池、日志缓冲池和SOFTMAX等日志相关参数之后，问题依然没有改善。同时注意到在挂起发生时，系统的CPU、I/O都不繁忙，相反都比较空闲。

当经过2～3分钟之后，挂起状态会被自动解除，同时数据库上的操作都恢复继续执行。DB2的诊断日志文件db2diag.log中也没有记录任何错误信息。

下面我们讲解针对这个问题的诊断步骤：

为了判断问题发生时DB2的运行状况，在DB2数据库运行的系统上，使用如下命令捕捉DB2进程的堆栈信息和操作系统CPU、I/O信息：

1. db2pd -stacks -repeat 8
2. vmstat 4 > vmstat. out
3. iostat 4 > iostat. out
4. db2pd -eve -repeat 12 > pdeve.` date  +%Y%m%d.%H%M%S`
--循环捕捉db2进程信息：
while :;
do
ps -elf|grep db2 > ps. out .` date  +%Y%m%d.%H%M%S`
sleep 10
done
6. db2  update  monitor switches using lock  on  bufferpool  on  statement  on
while :;
do
db2  "get snapshot for all on sample"  > snap.` date  +%Y%m%d.%H%M%S`
sleep 10
done

数据收集完成后，在快照中发现如输出结果9.47中的信息：

Application handle = 1445
Application status =  Commit  Active
Status change  time  = 12/07/2008 11:10:12.433060
Application code page = 1386
Application country/region code = 1
DUOW correlation token = B6F80323.BF0C.030574102402
Application  name  = Ptran013
... ...
Snapshot  timestamp  = 12/07/2008 11:11:36.980672
Coordinator agent process  or  thread ID = 929880

可以看到应用1445发起COMMIT的时间("Status change time")是"12/07/2008 11:10:12.433060"，而快照的捕捉时间("Snapshot timestamp")是"12/07/2008 11:11:36.980672"。在这超过80秒的时间中，它一直处于"Commit Active"状态。

"Commit Active"表示当前应用已经通知DB2提交未完成的事务，但是DB2还没有完成全部的提交动作。一个提交动作持续这么长时间是比较少见的，这可能说明 DB2由于某些原因无法完成提交。继续观察快照发现，还有其他超过20个应用同样处于"Commit Active"状态。

在执行"db2pd-stacks"命令收集的堆栈文件中，找到对应929880("db2agent"进程ID)或者其他处于"Commit Active"状态的应用程序的文件，可以看到类似如下的输出信息：

sqlpgWaitForLrecOnDisk__FP9SQLP_DBCBUl
sqlpWriteLR__FP20sqle_agent_privatecbUlN42P14SQLP_LREC_PARTT2P9SQLP_LSN8

这表明它正在向日志文件写入记录。DB2LOGGW后台进程负责日志记录的写入，可以看到它的调用堆栈如下所示：

semop
sqloNLCKLock
sqluhLock__FP12SQLUH_HANDLE
VerifyHistoryFilesAndOptToRecover__FPP12SQLUH_HANDLEPcCb
sqluhOpen__FPP12SQLUH_HANDLEPcUl
... ...

它正在等待获取在HISTORY FILE上的一个文件锁。 继续分析其他的堆栈输出文件，发现当时正在操作HISTORY FILE的进程是另一个"db2agent"进程295218，具体信息如下所示：

lseek64
sqloseek
sqluhReadEntry__F12SQLO_FHANDLEP11SQLUH_ENTRYP14SQLUH_WORKAREAPcN34PUi
sqluh_get_next_history_file_entry
sqluhGetEntryDRDA__FP5sqldaT1P13sqle_agent_cbP5sqlca
sqlerKnownProcedure__FiPcPiP5sqldaT4P13sqlerFmpTableP13sqle_agent_cbP5sqlca
... ...

它已经打开了HISTORY FILE，并且正在一条条地读取其中的记录。在"db2pd-eve"的输出中，找到对应这个"db2agent"进程的客户端进程，具体信息如下所示：

Address AppHandl [nod-index] AgentPid Priority Type State ClientPid Userid
CientNm
Rowsread Rowswrtn LkTmOt DBName
0x078000000027D4C0 1291 [000-01291] 295218 0 Coord Inst-Active 950376 db2icps
db2hmon 0 0 NotSet n/a

终于，发现是DB2HMON进程发起的这个操作。从DB2 V8.2开始，DB2HMON进程成了一个独立的服务器端进程，它不再受到HEALTH_MON参数的控制。当DB2实例启动的时候，DB2HMON进程 和实例主进程一起被启动。即使AUTO_MAINT设置为OFF，DB2HMON进程仍然会每两个小时就被唤醒一次，执行自动维护的评估性操作。当它执行 某些评估的时候，会扫描HISTORY FILE。在扫描期间，会妨碍其他应用程序修改HISTORY FILE。这种唤醒操作是无法停止的，除非将如下DB2注册表变量关闭：

db2set DB2_FMP_COMM_HEAPSZ=0

回想前面问题发生时的情景：

(1) 每两个小时，DB2HMON进程被唤醒，发起一个连接到数据库服务器上，然后开始扫描HISTORY FILE文件。

(2) 这时如果数据库上的某个日志文件被写满，由于日志归档已经打开，所以DB2会归档这个已经满的日志文件。但是由于在这之前DB2需要读取HISTORY FILE中的信息，所以会申请获得文件锁。

(3) 于是，发生了锁等待。这不是DB2内部的锁等待，而是操作系统的文件级别上的锁等待，所以从DB2观察不到锁等待的现象。 当HISTORY FILE的大小随着DB2的使用时间不断增长之后，DB2HMON进程扫描这个文件所花费的时间也会随之增长。DB CFG中有一个参数REC_HIS_RETENTN，用于控制HISTORY FILE中信息的保留时限。它的默认值是366天。

使用下面的命令，可以修改这个默认设置：

db2  update  db cfg  for  <db_name> using REC_HIS_RETENTN <number_of_days>

也可以使用命令截断HISTORY FILE：

db2 prune history yyyymmddhhmmss

当HISTORY FILE的大小被缩小后，DB2HMON扫描它所花费的时间大大减少，这个挂起的问题就不再发生了。

上面的这个案例也许在实际生产中意义不大，举这个案例更重要的是希望读者学会问题诊断和分析的思路流程。这对你以后实际生产中的面对各种各样的问题诊断非常重要