内容


DB2 系统临时表空间过大引发的性能问题

Comments

系列内容:

此内容是该系列 2 部分中的第 # 部分:

敬请期待该系列的后续内容。

此内容是该系列的一部分:

敬请期待该系列的后续内容。

这是某银行业务系统发生的一次真实案例,从某一天开始,业务人员陆续反映系统响应变慢,同时 DB2 数据库监控频繁捕捉到数据库 ACTIVE SESSION 数量达到 50 以上,登录 DB2 数据库服务器上发现多个语句执行时间变长。这一切现象看起来是典型的性能问题,于是开始按部就班的检查 CPU,内存,I/O,LOCK WAIT,缓冲池命中率,抓取执行时间长的语句并检查执行计划,一番努力之后没什么效果。后来终于发现,一直默默无闻几乎无人关心的 DB2 系统临时表空间 TEMPSPACE1 居然有 10G 之大,并且是性能下降的"罪魁祸首"。

本文将介绍这个性能问题的分析处理过程,解析 DB2 TEMPSPACE1 空间过大如何一层一层的影响查询语句的性能,并提供了解决方法。这其中涉及到常用性能分析步骤,LATCH 分析方法,STACK 收集和分析技巧,甚至如何用 db2trc 工具"暂停"DB2 实例等,对读者分析性能问题有一定的参考意义。

性能问题的初步确认

如本文开头提到的,业务人员陆续反映某业务系统响应变慢,同时数据库监控频繁捕捉到数据库 ACTIVE SESSION 数量达到 50 以上,如果说业务人员的凭感觉做出的反馈有可能有偏差,或者还会考虑是否应用程序有问题,那么看到数据库 ACTIVE SESSION 数量高则是很有可能是数据库发生了问题,作为运维 DBA 马上开始紧张起来。查看监控系统中 ACTIVE SESSION 数量历史曲线,之前 ACTIVE SESSION 数量一直在 10 个以内,偶尔有达到 30 个的情况,这几天较为频繁的超过 30 个。

ACTIVE SESSION 数量即活动会话数是 DB2 数据库监控中一个重要的指标,可以从 db2top 中方便的看到当前的 ACTIVE SESSION 数量(db2top -d <dbname>,然后输入交互指令'd'),并且以默认 2 秒的间隔持续刷新,如图 1 所示。

图 1. db2top 查看 ACTIVE SESSION 数量

这个 ActSess 指标是指数据库当前正在执行的会话数,也就是正在执行的 application 数量,还可以通过 db2 LIST APPLICATIONS SHOW DETAIL 的结果进行统计获得。准确的说,正在处理 SQL 语句请求的会话都计入 ACTIVE SESSION,而 SQL 语句处理过程从编译到执行完成这个过程会出现 Compiling,UOW Executing 等状态,如果有锁等待还会出现 Lock Waiting 状态。COMMIT 也是一个语句,COMMIT 执行过程中可能看到 Commit Active 状态。如果启用了 WLM 的并发限制,正在排队等待的会话处于 Queued 状态。以上这些状态的会话都计入 db2top 中的 ActSess 数量。应用程序在一个事务(TRANSACTION)中执行完一条语句而下一条语句还没开始执行,这时 APPLICATION 的状态是 UOW Waiting,不计入 ACTIVE SESSION 数量。看到 ActSess 数量高,需要再看一下具体是哪些状态,可以通过在 db2top 中输入交互指令'l'(小写的 L)进入 SESSIONS 页面,本次的问题中活动会话都是 UOW Executing 状态。

一般的联机事务处理(OLTP)系统的 ACTIVE SESSION 数通常在 10 个以内,较为繁忙的系统可能达到二三十个,如果更高就需要考虑进行系统扩容。当一个系统平时的 ACTIVE SESSION 数量只有几个,突然频繁的达到几十个,那有两种可能,一是业务系统变忙,例如业务访问量激增;另一个种可能就是出现了性能问题,SQL 语句执行时间变长。当然也有可能是两种情况的组合,即业务访问量激增导致某种竞争,从而 SQL 语句执行时间变长。

基于对某银行业务系统的理解,并与业务系统负责人确认,可以肯定的是业务访问量没有增加。这样就基本确定了是数据库出现性能问题,SQL 语句执行时间变长。

快速排除法

可以快速的排除数据库服务器资源问题,CPU 利用率在正常范围内,操作系统内存使用量正常。根据 db2top 结果(如图 1)快速的判断数据库缓冲池命中率(HitRatio)正常,没有 LOCK WAIT,从右下角四个参数 AvgPRdTime(Average Physical Read time),AvgDRdTime(Average Direct Read Time),AvgPWrTime(Average Physical Write time)和 AvgDWrTime(Average Direct Write time)可以判断 I/O 正常。注意到 Deadlocks 为 218,但这是一个累计值而且不会影响性能,还注意到有 SortOvf(Sort Overflow)为 10,有点儿高但考虑到应用程序的 SQL 语句用了较多的排序,所以有一些排序溢出应该不是主要问题。

另外,已经确认了是数据库自身的问题,就不需要考虑网络故障的可能性了。

抓取并分析执行时间长的 SQL 语句

接下来分析执行时间长的 SQL 语句。可以通过 db2top 来看缓存(PACKAGE CACHE)中的动态 SQL(在 db2top 的界面输入交互指令'D'),还可以在这个界面继续输入交互指令'z',在上方会出现提示"Column number for descending sort:",然后输入数字 4 回车,会根据 Avg ExecTime 进行排序,如图 2 所示。

图 2. db2top 查看动态 SQL 执行时间

在图 2 中看到,前几条 SQL 语句的 Avg ExecTime 即平均执行时间最长的接近 4 秒,但是 Num Execution 即执行次数都只有有限几次,这应该是由于应用程序中的 SQL 语句没有使用变量绑定方式而且直接拼凑 SQL 语句,导致几乎每条 SQL 对 DB2 来说都是新的语句。尽管只看到执行几次的 SQL 的平均执行时间,还是可以推测确定所有这种语句执行时间都比较长。

MON_CURRENT_SQL 管理视图

对于 ACTIVE SESSION 数量高的情况,可以用 MON_CURRENT_SQL 管理视图来查看当前正在执行的 SQL 语句(包括动态 SQL 和静态 SQL),查询语句如清单 1 所示,结果如图 3 所示(为了便于阅读,图 3 中的结果中有一些字段没有显示)。

清单 1. 使用 MON_CURRENT_SQL 管理视图

db2 "SELECT COORD_MEMBER MEMBER,
VARCHAR(SESSION_AUTH_ID,10) USER,
VARCHAR(CLIENT_APPLNAME ,10) APPNAME,
ELAPSED_TIME_SEC ELAPSEDTIME,
VARCHAR(ACTIVITY_STATE ,10) STATE,
TOTAL_CPU_TIME,
ROWS_READ,
ROWS_RETURNED,
QUERY_COST_ESTIMATE,
DIRECT_READS,
DIRECT_WRITES,
VARCHAR(STMT_TEXT,2000) as STMT_TEXT
FROM SYSIBMADM.MON_CURRENT_SQL
ORDER BY ELAPSED_TIME_SEC DESC"
图 3. MON_CURRENT_SQL 查询结果

在图 3 中可以看到部分正在执行的 SQL 语句并且按照已经运行时间(ELAPSED TIME,单位秒)进行排序,还有一些时间较短的语句在图 3 中没有显示,总共有接近 30 条,即当前 ACTIVE SESSION 数量接近 30。

需要注意的是,用 MON_CURRENT_SQL 管理视图来查看当前正在执行的 SQL 语句,需要根据情况执行多次才能捕捉到 ACTIVE SESSION 数量高的情况,并且抓取时 SQL 语句并没执行完,因而显示的 ELAPSED TIME 比语句的完整执行时间要短一些。

MON_GET_PKG_CACHE_STMT 表函数

还可以使用 MON_GET_PKG_CACHE_STMT 表函数来查询当前 PACKAGE CACHE 中 SQL 语句(包括动态 SQL 和静态 SQL)的执行信息,这是一个非常强大的工具,能够返回非常多的信息包括各种时间信息,例如语句执行过程总的等待时间、等待锁的时间、等待排序的时间等等。当发现语句执行时间长时,可以用这个表函数来分析时间的分布情况,是消耗在等待上还是读数据上或者其他因素。查询语句如清单 2 所示,结果在图 4 中。清单 2 的语句并不是直接查询表函数来显示结果,而是计算了每个语句的平均执行时间,以及各项等待时间在总的执行时间的百分比,这样结果更直观一些,但需要注意的是示例查询中只选择了一部分字段,还可以根据情况增加更多的字段,例如增加 TOTAL_EXTENDED_LATCH_WAIT_TIME 来查看 LATCH 等待时间。

清单 2. 使用 MON_GET_PKG_CACHE_STMT 表函数
db2 +w "SELECT MEMBER,
NUM_EXECUTIONS,
STMT_EXEC_TIME,
decimal((TOTAL_ACT_WAIT_TIME / double(STMT_EXEC_TIME)) * 100, 5, 2) as pct_wait,
decimal((POOL_READ_TIME / double(STMT_EXEC_TIME)) * 100, 5, 2) as pct_read,
decimal((LOCK_WAIT_TIME/double(STMT_EXEC_TIME)) * 100, 5, 2) as pct_lock,
decimal((LOG_DISK_WAIT_TIME / double(STMT_EXEC_TIME)) * 100, 5, 2) as pct_log,
decimal((TOTAL_SECTION_SORT_TIME / double(STMT_EXEC_TIME)) * 100, 5, 2) as pct_sort,
CAST(FLOAT(STMT_EXEC_TIME)/FLOAT(NUM_EXECUTIONS) as decimal(10,3)) as AVG_EXEC_TIME,
VARCHAR(STMT_TEXT,500) AS STMT_TEXT
FROM TABLE(MON_GET_PKG_CACHE_STMT(NULL,NULL,NULL,-2))
WHERE NUM_EXECUTIONS >1 and STMT_EXEC_TIME>0
图 4. MON_GET_PKG_CACHE_STMT 查询结果

在图 4 中可以看到,这些语句的 AVG_EXEC_TIME(平均执行时间)在 2~6 秒不等,其中有 5 条语句(with 开头的语句)的 PCT_WAIT 在 95%以上,也就是说这 5 条的执行时间花在了等待上,但是等待的不是 READ、Lock、写事务日志或者排序,而且别的原因。在清单 2 语句的基础上继续增加查询字段,会发现这些语句是在等待 LATCH 上。另外 5 条语句都是调用存储过程的,从这里看不出来时间分布。

结合多种方式获取的 SQL 语句来看,有多条 SQL 语句执行时间为 3~6 秒,对于 OLTP 系统这已经是非常慢了,在并发量稍大的情况就会出现 ACTIVE SESSION 数量高。这些慢的语句中有一部分是因为 LATCH 等待,还有一部分没有等待。这时候可以开始着手优化 SQL,作者也确实这样做了,先是快速的通过创建索引解决了几个有全表扫描的 SQL,然后又去梳理并且尝试优化那些很长且逻辑复杂的 SQL 语句。但是,那些逻辑复杂的长 SQL 并不是最近才上线的啊,会不会以前也是这么慢,最近没有应用程序变更啊(也没有数据库变更),现在努力的方向不对吧。。。及时的打住,进行思考。

分析发现 LATCH 问题

刚才通过 MON_GET_PKG_CACHE_STMT 表函数已经发现有 SQL 语句慢在 LATCH 等待了。其实在之前的快速排除法时,已经用 db2pd -latches 检查过 LATCH 情况,没有发现什么异常。再次较长时间的用命令 db2pd -latches -rep 2 检查 LATCH 情况,这个命令中的"-rep 2"是每隔 2 秒检查一次 LATCH 情况并持续输出到屏幕上。这次发现 LATCH 结果中有重大异常,每隔一段时间会出现较多的 LATCH 等待情况,时间间隔不固定。其中一次 LATCH 结果如图 5 所示。

图 5. 检查 LATCH 情况

在图 5 中看到 EDU ID 11665(Holder)拿着类型叫做"pool_table_latch"的 LATCH,而 ID 2877,2981 等 23 个 EDU 在等待这个 LATCH。这就意味着某个操作拿着 LATCH 阻塞了其他 23 个操作的执行,这时的 ACTIVE SESSION 数量至少是 24 个。

简单的介绍一下 DB2 中的 LATCH 机制。尽管 DB2 一些表函数可以提供 LATCH 相关信息,例如上文提到的 TOTAL_EXTENDED_LATCH_WAIT_TIME 监控元素,但在 DB2 的文档中没有找到任何对 LATCH 的介绍性内容。可以这样理解 DB2 中的 LATCH,其目的是为了保证 DB2 多线程访问内部共享资源的一致性。举例来说,例如 DB2 内存中有一个 PREFETCH QUEUE 的数据结构,当处理用户请求的 EDU(COORDINATOR EDU)需要进行预取的时候,就向这个 QUEUE 中增加预取任务,同时 DB2 PREFETCHER EDU(多个线程)不停地从这个 QUEUE 中读取任务,为了协调用户请求 EDU 和 PREFETCHER EDU 对 QUEUE 的访问,就需要在每次访问时先获取一个 LATCH,而其他 EDU 则需要等待 LATCH 释放后才能获取。也可以简单的把 LATCH 理解为 DB2 内部的一种轻量锁机制。

回到 pool_table_latch 的问题上。由于 LATCH 是 DB2 内部机制,没有任何文档或者网站供用户查询 LATCH 的含义和出现的场景,而且从 LATCH 名字的看似眼熟的字面意思也得不到什么信息,可以说对于这个 latch 也就一无所知了。由于 LATCH WAIT 在几秒钟之后就清除了,所以也很难及时获取 Holder 和 Waiter EDU 当前正在执行的操作。看似困难重重,但办法总是有的,我们还可以通过收集 STACK 信息结合 LATCH 信息来进行分析。

用 db2pd 收集 STACK 信息

db2pd 中提供了收集 DB2 运行的 STACK 信息的功能,这对于分析 HANG 的问题非常有用。这个功能也可以用来辅助分析 LATCH WAIT 问题,因为 db2pd 在收集 STACK 信息的同时还收集了每个 EDU 当时的 LATCH 信息(还包括 LOCK 信息,但 LOCK WAIT 问题通常用别的方法例如 db2pd -wlocks 或者 EVENT MONITOR 就可以解决)。可以使用清单 3 的命令收集 STACK 信息。

清单 3. 收集 STACK 信息的命令

cd /tmp
mkdir stack0531
db2pd -stack all dumpdir=/tmp/stack0531 -rep 3 10

db2pd 默认的把收集的 STACK 结果文件放在 DIAGPATH 目录中,在清单 3 中的 db2pd 命令指定了 dumpdir,这样可以把 STACK 结果放到指定的目录中。同时指定了"-rep 3 10",即每隔三秒收集一次,连续收集 10 次,这是因为之前的 LATCH WAIT 现象不是一直存在,需要持续的收集 STACK 信息。db2pd 命令完成之后,到指定的目录中检查 STACK 结果文件是否包含 pool_table_latch,如清单 4 所示,如果没有捕捉到,则继续收集 STACK。需要注意的是,如果是生产环境并且数据库系统比较繁忙,收集 STACK 信息会明显消耗系统资源并影响数据库性能,因此收集 stack 信息需要谨慎。

清单 4. 检查 STACK 结果文件

> cd /tmp/stack0531
> grep pool_table_latch *stack.txt
20160.10783.003.stack.txt:Holding Latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 9032, File: sqlmonss.C HoldCount: 1
20160.10783.003.stack.txt:Holding Latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 9032, File: sqlmonss.C HoldCount: 1
20160.10789.003.stack.txt:Holding Latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 9032, File: sqlmonss.C HoldCount: 1
20160.10789.003.stack.txt:Holding Latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 9032, File: sqlmonss.C HoldCount: 1
20160.5721.003.stack.txt:Waiting on latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 11384, File: sqlbpool.C
20160.5817.003.stack.txt:Waiting on latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 11384, File: sqlbpool.C
20160.6037.003.stack.txt:Waiting on latch type: (SQLO_LT_SQLB_PTBL__pool_table_latch) -Address: 
(0x7eeebae94750), Line: 11384, File: sqlbpool.C
<省略部分结果>

从清单 4 中可以看到,收集的 STACK 信息中已经发现了 pool_table_latch,其中一些 EDU 正在 Holding 这个 LATCH,另一些 EDU 正在 Waiting 这个 LATCH。进入相应的*.stack.txt 文件查看相应的 STACK,发现 Holder 的 STACK 如清单 5 所示,Waiter 的 STACK 如清单 6 所示。

清单 5. Holder EDU 的 STACK

省略部分内容
0x00007F00F230F435 __xstat64 + 0x0015
0x00007F00F74A0EB8 sqlofindn2 + 0x04f8
0x00007F00F46F806F _ZN13SQLB_FIND_BUF4nextEPP16sqlo_filefindbuf + 0x007f
0x00007F00F846ADEE _Z27sqlbMonSMSGetContainerPagesP12SQLB_POOL_CBiPj +0x010e
0x00007F00F846C3C2_Z22sqlbSnapshotTablespaceRK16sqlm_bp_int_infoP16sqeLocalData…
0x00007F00F697F932 _Z12sqlmonssagntj13sqm_entity_idP6sqlmaijPvP14sqlm_collectedttP5…
0x00007F00F8C1435C _Z20sqlmPdbRequestRouterP8sqeAgent + 0x057c
0x00007F00F65749DC _Z21sqleProcessSubRequestP8sqeAgent + 0x02dc

清单 6. Waiter EDU 的 STACK

省略部分内容
0x00007F00FA4F6D49 _ZN17SQLO_SLATCH_CAS6418getConflictComplexEm + 0x0579 
0x00007F00F74AAEB5 _ZN17SQLO_SLATCH_CAS6411getConflictEm + 0x0055
0x00007F00F47591FB _Z22sqlbGetSysTempDatapoolPtP12SQLB_GLOBALSi + 0x07cb
0x00007F00F482DE94 _Z23sqldInternalCreateTableP8sqeAgentP19SQLD_TABLECRE…
0x00007F00F4836416 _Z19sqldTableCreateTempP8sqeAgentPtS1_hmmiP10SQLD_FI…
0x00007F00F9B2D98C _Z8sqlritt2P8sqlrr_cb + 0x017c                              
0x00007F00FA43056B _Z16sqldEvalDataPredP13SQLD_DFM_WORKPmP10SQLD_D…
0x00007F00FA56791A _Z8sqlsfetcP8sqeAgentP8SQLD_CCBiP10SQLD_DPREDPP10…
0x00007F00FA5483A8 _Z10sqlriFetchP8sqlrr_cbP9sqlri_taol + 0x0178              
0x00007F00FA552047 _Z7sqlritaP8sqlrr_cb + 0x0577

有了 Holder 和 Waiter 的 STACK 信息,读者可能会问,这些函数更是 DB2 内部信息,我们更加看不懂。其实 STACK 里提供的信息已经很多了,通过观察 STACK 里的函数名字以及调用关系,猜测函数名字的字面意思,结合 DB2 架构相关的知识,基本上可以看出来这些 STACK 相应的操作类型或者正在访问的对象类型。

清单 5 中 Holder EDU 的 STACK 中有两个看着眼熟的函数名字,sqlbSnapshotTablespace -> sqlbMonSMSGetContainerPages,从字面意思上可以猜到,这个 EDU 在对表空间做 SNAPSHOT,进一步是在 MONITOR SMS 表空间时获取容器(CONTAINER)的数据页(PAGE)。这个操作为什么要占有 pool_table_latch 呢? 这个问题暂且不追究。清单 6 中 Waiter EDU 的 STACK 里有这样的函数以及调用关系,sqldTableCreateTemp -> sqldInternalCreateTable -> sqlbGetSysTempDatapool,可以直观的猜测到这是在创建内部临时表并且使用系统临时表空间,结合 sqldEvalDataPred 函数(evaluate predicate)可以基本上确认这是在执行一个查询 SQL 并且用到了临时表。

到了这一步,我们基本上可以做出判断,对表空间进行 SNAPSHOT 操作执行时间较长,占有 LATCH 从而阻塞了查询操作,而 SNAPSHOT 慢的原因应该是与 SMS 表空间的 CONTAINER 的数据页(PAGE)有关。至于为什么有频繁的对表空间 SNAPSHOT 的操作,这是因为数据库监控系统在每个数据库服务器上部署的监控代理(AGENT)在定期的收集表空间信息。

用 analyzestack 工具分析 STACK 信息

刚才分析 STACK 的时候采用的是比较简单粗暴的方法,DB2 "悄悄的"提供了一个非常方便的 Perl 脚本程序 analyzestack,放在 sqllib/pd 目录下,主要功能是能够将指定目录中所有单独的*.stack.txt 文件中相同的 STACK 进行汇总和统计,并能分析 LATCH 信息。为什么说是"悄悄的",这是因为这个 Perl 脚本之前是 IBM DB2 支持部门使用的内部工具,后来才放到 DB2 产品中,但直到现在从 DB2 知识中心或者其他网站找不到任何关于这个脚本的介绍,同时在脚本开头的声明中提到,"analyzestack is supplied as-is as an example of how to perform this function. There is no warranty or support.",这样看来这个工具没有 DB2 官方支持。至于这个 Perl 脚本的用法,只能通过-help 来看了。清单 7 是 analyzestack 用法的简单示例(并非在本文分析问题所在的 DB2 环境中演示)。

清单 7. analyzestack 基本用法
> perl ~/sqllib/pd/analyzestack -d 50 -i /tmp/stack -l

**** Found that the trap files are Linux trap files **** 

**** You have chosen not to get the missing functions. If you want them, pls. use the -fix option and
**** run it on the correct platform with the right build

Slurping 56 trap files ..
........................................................

Analyzing the trap files ..please wait
.............................

Analyzing Latches ..
**** NO LATCHWAIT DETECTED ****
No case of Waiters waiting on any Holder
Printing the Holder and the Waiter info nevertheless

Please check the following files:
=======================================

LatchAnalysis.out
StackAnalysis.out

Analysis Complete ...

在清单 7 执行 analyzestack 的命令中,-d 参数指定了对比 STACK 时比较的函数个数,-i 参数指定*.stack.txt 文件所在的目录,也可以指定多个具体的*.stack.txt 文件,-l 是进行 LATCH 分析。analyzestack 会生成两个结果文件,默认文件名为 LatchAnalysis.out 和 StackAnalysis.out,也可以通过参数进行指定文件名。这个脚本更具体的用法读者可以自行探索,本文不再展开。

问题解决

继续分析问题,接下来去检查数据库中的表空间,这时才发现 db2 LIST TABLESPACES SHOW DETAIL 都需要若干秒钟才能执行完。检查发现,TEMPSPACE1 居然有 10G!检查结果如清单 8 所示。

清单 8. TEMPSPACE1 信息

Tablespace ID                        = 1
 Name                                 = TEMPSPACE1
 Type                                 = System managed space
 Contents                             = System Temporary data
 State                                = 0x0000
   Detailed explanation:
     Normal
 Total pages                          = 354661
 Useable pages                        = 354661
 Used pages                           = 354661
 Free pages                           = Not applicable
 High water mark (pages)              = Not applicable
 Page size (bytes)                    = 32768
 Extent size (pages)                  = 32
 Prefetch size (pages)                = 768
 Number of containers                 = 4

> ls -al /db2data/oap/data4/db2oap/NODE0000/OAP/T0000001/C0000003.TMP
-rw------- 1 db2oap dbadm 1048576 May 22 09:19 SQL04313.MEMBER0000.TDA
-rw------- 1 db2oap dbadm 1048576 May 22 09:18 SQL04314.MEMBER0000.TDA
-rw------- 1 db2oap dbadm 1048576 May 22 09:18 SQL04315.MEMBER0000.TDA
-rw------- 1 db2oap dbadm   32768 May 22 09:18 SQL04316.MEMBER0000.TDA
-rw------- 1 db2oap dbadm 1048576 May 22 09:18 SQL04317.MEMBER0000.TDA
-rw------- 1 db2oap dbadm 1048576 May 22 09:18 SQL04318.MEMBER0000.TDA
-rw------- 1 db2oap dbadm 1048576 May 22 09:18 SQL04319.MEMBER0000.TDA
省略部分内容

正常情况下 TEMPSPACE1 应该非常小,现在却有 10G,导致 LIST TABLESPACES SHOW DETAIL 执行很慢。这时想起来去数据库监控系统查看表空间大小历史曲线,发现某个时间 TEMPSPACE1 的大小从 0 暴涨到 10G。在 IBM 网站上搜索发现这样一个 Technote,"Tablespace TDA files not being deleted and are filling up the filesystem",介绍的是 SMS 临时表空间中的 TDA 文件可能会遗留在表空间中并占满文件系统的问题,但这是 Work as Design 的。根据 Technote 提供的方法,安排维护窗口对数据库进行 deactivate/activate,发现这些临时表空间被释放,然后 LIST TABLESPACES SHOW DETAIL 运行正常,对数据库运行状态进行监控一段时间确认,之前的性能问题也完全消失,ACTIVE SESSION 回到个位数。注意必须是 deactivate/activate 数据库,只重启数据库实例无法释放这些临时表空间。

至于临时表空间达到 10G 的原因,应该是与之前那个时间点发生的事件有关,有一个瞬间 ACTIVE SESSION 数量达到 800 多个,大量的 SQL 语句同时使用了临时表空间,数据库没有崩溃,SQL 语句也执行成功,但在临时表空间留了一堆 TDA 文件,变成了现在踩到的这个雷。

一个特别的小实验作为尾声

根据上面的分析和解决过程,我们认定了表空间信息查看操作(例如 LIST TABLESPACES SHOW DETAIL 等)会占有 pool_table_latch,我们利用 db2trc 工具做一个小实验来再次验证一下。

db2trc 是一个非常有用的工具,能够获取 DB2 运行过程中调用过的函数信息。不仅如此,还可以使用 db2trc 来"暂停"DB2 的运行,让我们有机会从容的收集特定信息。

实验过程如下:

(1)在第一个终端窗口依次执行命令:

> db2 CONNECT TO mydb

> db2trc on -crash DB2.SQLB.sqlbSMSGetContainerPages.entry -suspend

Trace is turned on

> db2 LIST TABLESPACES SHOW DETAIL

会发现在显示了第一个表空间 SYSCATSPACE 的信息之后停住了,这是因为 DB2 EDU 被 db2trc 命令 suspend 住了。

(2)在第二个终端窗口执行 db2pd 命令就可以看到 pool_table_latch:

> db2pd -latches

0x00007F8A39DD16D0 22 0 Unknown 3057 SQLO_LT_SQLB_PTBL__pool_table_latch 1

(3)在第二个终端窗口继续输入 db2trc off 回车后,会发现第一个终端窗口的 LIST TABLESPACES SHOW DETAIL 得以继续执行并显示了所有的表空间信息。

通过这个实验,确认了 LIST TABLESPACES SHOW DETAIL 操作会占有 pool_table_latch。至于实验中 db2trc -crash -suspend 的用法,因为用到的机会极少,本文不展开介绍。

总结

问题终于解决了,先是一个意外的高峰(ACTIVE SESSION 800 多)以及 DB2 Work as Design 的临时表文件处理机制,保留了大量的 TDA 文件引起的系统临时表空间过大,然后 DB2 监控系统需要定期的查看表空间信息,系统临时表空间过大导致查看表空间信息慢,再然后查看表空间信息会占有 pool_table_latch,阻塞了业务应用中需要使用临时表空间的 SQL 语句,结果导致了 SQL 语句执行时间变长,表现为 ACTIVE SESSION 高,业务系统响应变慢,这是一条长长的因果关系链。

在问题分析过程中用到了 db2top 工具、抓取 SQL 语句方法、收集 LATCH、收集和分析 STACK,以及额外的用 db2trc "暂停"DB2 等多种工具和方法,读者可以在其他的问题分析过程中用到。

有人可能已经发现了,本文的问题其实是发生在 DB2 pureScale 环境中,所以上文的图中会出现"Database Member 2"或者查询结果中出现 MEMBER 的值不为 0 的情况。这也是为什么数据库监控系统定期收集表空间信息但问题现象却没有时间规律的原因之一,因为监控代理在 DB2 pureScale 的 4 个 MEMBER 上各自执行(尽管对于收集表空间信息来说没有必要),收集信息的时间并不统一。由于这个问题的原因以及分析过程与 DB2 pureScale 特性不直接相关,因此本文没有特别指出。

另外,作者通常是在问题解决之后设计场景来重现问题然后逐步的进行解析,并且所有的步骤和命令读者都可以在各自的环境进行重演。但本文有所不同,没有了详细的重现过程而是依照实际问题的分析过程,读者可能会感觉比较乱,非常感谢您的耐心阅读。

最后,本文仅代表作者观点,不代表 IBM DB2 官方观点。

参考资料

学习

获得产品和技术

  • 使用可直接从 developerWorks 下载的 IBM 产品评估试用软件 构建您的下一个开发项目。
  • 现在可以免费使用 DB2 。下载 DB2 Express-C,这是为社区提供的 DB2 Express Edition 的免费版本,它提供了与 DB2 Express Edition 相同的核心数据特性,为构建和部署应用程序奠定了坚实的基础。

讨论


评论

添加或订阅评论,请先登录注册

static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=10
Zone=Information Management, Big data and analytics
ArticleID=1046942
ArticleTitle=DB2 系统临时表空间过大引发的性能问题
publish-date=06222017