问题描述:在一个运行于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扫描它所花费的时间大大减少,这个挂起的问题就不再发生了。
上面的这个案例也许在实际生产中意义不大,举这个案例更重要的是希望读者学会问题诊断和分析的思路流程。这对你以后实际生产中的面对各种各样的问题诊断非常重要