内容


developerWorks 图书频道

深入解析 DB2 —— 高级管理、内部体系结构与诊断案例,第 9 章

高级诊断

Comments

系列内容:

此内容是该系列 # 部分中的第 # 部分: developerWorks 图书频道

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

此内容是该系列的一部分:developerWorks 图书频道

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

在使用 DB2 数据库的过程中,发生一些这样或那样的问题和故障是不可避免的。在发生这些问题之后,如何及时和准确地找到故障原因并合理地处理这些问题就显得极为重要。本章介绍在 DB2 中的一些高级诊断工具和诊断方法。快速、合理地使用这些工具能够极大地提高 DBA 处理数据库故障的能力和效率。

本章介绍的工具有 db2dart 和 inspect、db2pdcfg、db2trc、db2_call_stack 和 db2nstck,并结合这些工具给出了大量的诊断问题的实例。

本章主要讲解如下内容:

  • db2dart 和 inspect
  • db2pdcfg
  • db2trc
  • db2_call_stack 和 db2nstck

9.1  db2dart 和 inspect

9.1.1  db2dart 和 inspect 概述

当 DB2 数据库出现异常后,可以使用 db2dart 或 inspect 命令查看整个数据库的一致性。 db2dart 命令可以用来验证数据库以及相关的数据库对象是否正确,是否存在问题;还可以用来显示数据库控制文件的内容,以便在重建数据库时从其他情况下无法访问的表中抽取数据。

如果想查看使用 db2dart 命令的相关语法,可以在当前 DB2 CLP 窗口中,执行 db2dart 命令 ( 不带任何参数 ),就可以看到其相关选项了。 db2dart 的基本语法是“ db2dart < database name > [ action ] [ options . . . ] ”,默认情况下,db2dart 实用程序将创建一个“数据库名 .RPT ”的报告文件。 db2dart 实用程序直接从磁盘中读取数据库中的数据和元数据,而不是通过 DB2 数据库管理器来进行访问。

使用 db2dart 实用程序时,需要注意,要保证该数据库上没有活动的数据库连接 ( 也就是说如果不取消激活数据库,那么 db2dart 将产生不可靠的结果 ) 。如果您在当前 DB2 CLP 窗口中,先连接示例数据库 SAMPLE,然后再执行“ db2dart sample /db ”命令,那么会有 FYI 提示信息,告诉你现在 SAMPLE 数据库上有一个活动的连接,请停掉所有的连接后再次执行 db2dart 命令,具体过程和提示信息如下所示:

C:\> db2 connect to sample 数据库连接信息
数据库服务器 = DB2 / NT 9.5.0 
 SQL 授权标识 = DB2ADMIN 
本地数据库别名 = SAMPLE 
 C:\> db2dart sample /db 
 FYI: An active connection to the database has been detected . 
 False errors may be reported . 
 Deactivate all connections and re-run to verify . 
 Warning : The database state is not consistent . 
 Warning : Errors reported about reorg rows may 
 be due to the inconsistent state of the database . 
 DB2DARTDB2DART Processing completed with warning ( s ) ! 
 Complete DB2DARTDB2DART report found in : 
 C:\DOCUME~1\ALLUSE~1\APPLIC~1\IBM\DB2\DB2COPY1\DB2\DART0000\SAMPLE.RPT

遇到这种情况,正确的做法是在当前 DB2CLP 窗口中,发出“ force applications all ”命令,断开所有的数据库连接,然后执行“ db2dart sample /db ”命令,具体过程如下所示:

C:\> db2 force applications all 
 DB20000I FORCE APPLICATION 命令成功完成。
 DB21024I 此命令为异步的,可能未能立即生效。
 C:\> db2 list applications 
 SQL1611W “数据库系统监视器”没有返回任何数据。
 C:\> db2dart sample /db 
 The requested DB2DART processing has completed successfully! 
 Complete DB2DART report found in: 
 :\DOCUME~1\ALLUSE~1\APPLIC~1\IBM\DB2\DB2COPY1\DB2\DART0000\SAMPLE.RPT

db2dart 命令成功完成,db2dart 执行结果显示正常,如果有错误的话,会提示有 ERROR 存在,所有的结果都会存储在 SAMPLE.RPT 中。打开 SAMPLE.RPT 文件,可以看到数据库诊断的详细信息,由于篇幅有限,这里只列示了部分信息,如下所示:

DART (V9.5) Report : 
 2008-04-02-23.28.24.531000 

 Database Name : SAMPLE 
 Report name : SAMPLE.RPT 
 Old report back-up : SAMPLE.BAK 
        Database Subdirectory : C:\DB2\NODE0000\SQL00002 
 Operational Mode : Database Inspection Only ( INSPECT ) 
 Action option : DB 
 Connecting to Buffer Pool Services . . . 
 Database inspection phase start . 
 Tablespace file inspection phase start . 
 Loading tablespace files . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 Inspecting next tablespace and associated containers . 
 7 tablespaces were identified and their containers checked . 
 Tablespace file inspection phase end . 
 SYSBOOT inspection phase start . 
 Data inspection phase start . Data obj : 1 In pool : 0 
 Data inspection phase end . 
 SYSBOOT inspection phase end . 
   SYSTABLES inspection phase start . 
 Data inspection phase start . Data obj : 5 In pool : 0 
 Data inspection phase end . 
 SYSTABLES inspection phase end . 
 Bufferpool file report phase start . 
 1 bufferpools were identified . 
 Bufferpool file report phase end . 
 Tablespace inspection phase start . Pool : 0 
 Tablespace-info inspection phase start . 
 Checking Table space ID : 0 
 Name = SYSCATSPACE 
 Extent size = 4 
 # of containers = 1 
 ---------------- 略 ---------------------------- 
 Table inspection end . 
 Tablespace inspection phase end . 
 Tablespace inspection phase start . Pool : 6 
 This is a temporary table space . Nothing to inspect . 
 Tablespace inspection phase end . 
 Database inspection phase end . 
 ---------------- 略 ----------------------------

我们在数据库的日常维护过程中,经常使用的 db2dart 命令的选项主要有 :

  • /DB ( 默认值 ):检查整个数据库。
  • /T:检查单个表。
  • /TSF:只检查表空间文件和容器。
  • /TSC:检查一个表空间的结构,但不包含它所属的那些表。
  • /TS:检查一个单独的表空间和它所属的那些表。
  • /DI:转储 (DUMP) 索引页结构。

下面我们举几个使用 db2dart 和 inspect 的案例。

9.1.2  利用 db2dart 查找停顿 (quiesce) 表空间的用户

在我们执行 quiesce 命令停顿一张表期间,该表所在的表空间无法被其他应用访问,要查找停顿表空间的用户,我们可以使用 DB2 LIST TABLESPACES SHOW DETAIL 命令。下面借助 db2dart 工具产生的报告,我们可以查询到发出 quiesce 命令的原始用户。具体执行步骤如下:

(1) 停止 DB2 实例:db2stop force 。

(2) 产生 db2dart 的报告:db2dart sample /dtsf 。

(3) 从报告中查找发出停顿命令的用户:根据命令执行结果的提示,找到 db2dart 产生的报告文件。打开该文件,对于停顿的表空间,可以在文件中找到信息如下所示:

Information for Tablespace ID: 2 
 ------------------------------------- 
 Tablespace name: USERSPACE1 
 Table space flags (HEX): 0101 
 Table space type: System Managed Space (SMS) 
 Page size: 4096 
 Extent size: 32 
 Prefetch size: 32 
 Version: 9 
 Tablespace state: 2 
 Number of quiescers: 1 
 Userid of quiescer: DB2INST1Quiesce state: 2——
注:16进制表示的表空间状态,可执行db2tbst 0x2命令查看16进制
的表空间状态的详细描述,命令输出结果:
Quiesced UpdateTbspace ID of quiesced object: 2 ——
注:表空间 ID,对应 SYSCAT.TABLES 表中的
 TBSPACEID Table ID of quiesced object: 15 ——
注:表 ID,对应 SYSCAT.TABLES 表中
的 TABLEID 字段
 EDU ID: 0 
 ......

定位表空间的 ID 和表的 ID 后,执行下面的 SQL 语句找出是哪个表:

db2 select tabname from syscat.tables where tbspaceid=2 and tableid=15 
 TABNAME 
 ------------------------------------------------------------------------ 
 STAFF 
 1 条记录已选择。

使用查找到的用户 DB2INST1 登录后,执行重置命令:

db2 quiesce tablespaces for table db2inst1.staff reset

命令执行成功后连接数据库,验证表空间状态正常。

9.1.3  db2dart 诊断高水位问题

我们在本书的第 4 章给大家讲过表空间高水位的概念,现在让我们来讨论一个实际生产中有关高水位的案例。

如果在一个表空间中删除了大量记录和表后,尝试缩小表空间大小以释放更多空间,那么会产生什么样的结果呢?下面让我们查看一下执行这个操作产生的问题诊断信息。当对这个表空间中的表执行完 reorg 命令后,用调整表空间命令 (alter tablespace) 缩小表空间失败,返回错误 SQL20170N( 表空间中没有足够的空间来执行指定的操作 ) 。具体信息如下所示:

alter tablespace tbspace1 resize "(all 15000k)" 
 DB21034E The command was processed as an SQL statement because it was not 
 a valid Command Line Processor command. During SQL processing it returned: 
 SQL20170N There is not enough space in the table space "TBSPACE1 " for 
 the specified action. SQLSTATE=57059

为什么缩小表空间大小会失败呢?

失败原因

在这个案例中,由于表空间缩小的空间大小大于在高水位标记之上的空间大小,因此调整表空间 (alter tablespace) 命令失败并且返回 SQL20170N 错误码。通常,你可以通过执行 reorg table 命令来释放被占用的扩展数据块,这样就可以降低表空间的高水位标记;但是如果高水位标记被空间映射页 (SMP) 持有,那么扩展数据块将不能被 reorg 命令移动。这个操作 (reorg) 或许就不能成功地降低高水位标记。
当执行 reorg table 命令时,如果满足下面的任何条件,那么都不能降低高水位标记:

  • 高水位标记位置是表的 PAGE 0 页 ( 一个表对象的开始页 ) 。
  • 内部页面管理页在高水位标记位置,如 SMP( 空间映射页 ) 或者 EMP( 扩展数据块映射页 ) 。
  • 执行一个表的在线 (ONLINE) 重组并且未指定临时表空间。这个重组表操作将导致更高的高水位,并且表不能重新覆盖原来的位置。
  • 由于重组后必须要进行索引集群,所以变长数据记录可能导致更差的页面填写。填写数据结果将导致表占用空间反而比 reorg 之前有所增加,也就是说高水位标记将升高而非下降。

问题总结

当我们看到某个 DMS 表空间的已用页数低于高水位标记时,则有可能通过如下方法降低高水位标记:

  • 重组表空间中的某个表。
  • 将某个表中的数据导出,然后将它删除,重新创建该表再将数据导入。

在以上的方法中,首先要找到持有高水位标记的那个表,这可以通过 db2dart 命令 ( 在停止实例后方可使用 ) 加上 /DHWM 选项,然后从命令所产生的报告文件中来获得相关信息。
首先要找到持有高水位标记的那个表,执行 db2dart 命令:

db2dart sample /dhwm /tsi 2 /rptn DLHW.TXT

查看 db2dart 的输出文件DLHW.TXT,查看持有高水准标记的表对象的信息:

Dump highwater mark processing -phase start. 
 Number of free extents below highwater mark: 168 
 Number of used extents below highwater mark: 139 
 Object holding highwater mark:Object ID: 4 
 Type: Table Data ExtentDump highwater mark processing -phase end.

执行下面的 SQL 语句找出具体是哪个表持有高水位标记:

select tabschema, tabname from syscat.tables where tableid = 4 and tbspaceid=2

而要获得对该表执行哪些操作可降低 HWM 的建议,可执行 db2dart 命令并且加上 /LHWM 选项,这样就可以从产生的报告文件中获得相关信息。使用 /LHWM 选项时,要求用户给出表空间的标识以及希望 HWM 降低到的页数 ( 虽然不能保证 HWM 一定能降低到这一用户期望值 ),如果该值使用 0,则表明由 DB2 将 HWM 降低到能够达到的最低值。如下所示:

db2dart sample /lhwm /tsi 8 /rptn lhwm.txt

执行 db2dart/lhwm 命令,查看建议信息:

Lower highwater mark processing -phase start. 
 Current highwater mark: 306Desired highwater mark: 124 
 Number of used extents in tablespace: 139 
 Number of free extents below original HWM: 168 
 Number of free extents below desired HWM: 122 
 Number of free extents below current HWM: 168 
 Step #1: Object ID = 4=> Offline REORG of this table using the LONGLOBDATA 
option (do not specify a temporary tablespace). 
 Table: DB2ADMIN.HIST1

在上面的例子中,我们可以通过对表 DB2ADMIN.HIST1 做离线重组来降低高水位。另外还可利用 db2dart 加 /RHWM 选项来移去 DMS 表空间中不再需要的空间映射数据块来降低 HWM,这些空间映射数据块在其映射的数据被删除时是不会被删除的。例如,如果高水位标记被一个不可挪动的空间映射页 (SMP) 扩展数据块持有,那么我们可以使用下面的命令来降低表空间的高水位标记:

db2dart sample/tsi 2/np 0/rhwm--注:选项 /np 0 会使高水位标记降至尽可能低的位置

db2dart 命令可以被用于在数据库停止的情况下移动那些 SMP 扩展数据块。

注意:

如果是可恢复数据库 ( 采用归档日志 ),那么在执行完此操作后数据库将被置于备份暂挂状态。这是因为 db2dart 不产生任何重做日志。因此,在执行完 db2dart 命令后必须对数据库做一个全备份操作。

9.1.4  db2dart 诊断数据页损坏问题

下面我们讨论一个实际的案例,请看下面的 db2diag.log 文件:

2008-09-22-11.46.45.864000+480 I805726H366 LEVEL: Error 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 FUNCTION: DB2 UDB, buffer pool services, sqlbReadAndReleaseBuffers, probe:13 
 RETCODE : ZRC=0x86020001=-2046689279=SQLB_BADP "page is bad" 
 DIA8400C A bad page was encountered. 
 2008-09-22-11.46.45.910000+480 I806094H413 LEVEL: Error 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 FUNCTION: DB2 UDB, buffer pool services, sqlbReadAndReleaseBuffers, probe:13 
 DATA #1 : String, 126 bytes 
 Obj={pool:34;obj:6;type:0} State=x27 Page=140354 Cont=0 Offset=140352 
 BlkSize=12 
 sqlbReadAndReleaseBuffers error: num-pages=8 

 2008-09-22-11.46.45.942000+480 I806509H593 LEVEL: Error 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 MESSAGE : SQLB_OBJECT_DESC 
 DATA #1 : Hexdump, 68 bytes 
 0x04B6B5DC : 2200 0600 2200 0600 0000 0000 003A A2A6 "..."........:.. 
 0x04B6B5EC : 40E5 0000 0000 0000 0000 0000 0000 0000 @............... 
 0x04B6B5FC : 0000 0000 0101 0000 2700 0000 0000 0000 ........'....... 
 0x04B6B60C : 0010 0000 2000 0000 0100 0000 2200 0600 .... ......."... 
 0x04B6B61C : 408C 7400 @.t.SQL1034C The database is damaged.
 2008-09-22-11.46.46.020000+480 I807104H356 LEVEL: Error 
 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 FUNCTION: DB2 UDB, buffer pool services, sqlbErrorHandler, probe:0 
 RETCODE : ZRC=0x86020001=-2046689279=SQLB_BADP "page is bad" 
 DIA8400C A bad page was encountered. 

 2008-09-22-11.46.46.020000+480 I807462H351 LEVEL: Error 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 FUNCTION: DB2 UDB, buffer pool services, sqlbErrorHandler, probe:0 
 DATA #1 : String, 75 bytes 
 Obj={pool:34;obj:6;type:0} State=x27--注:Obj={pool:34;obj:6;type:0} State=x27,
“pool”指的表空间ID,“obj”指的
对象IDPrefetcher Error, in sqlbProcessRange 

 2008-09-22-11.46.46.020000+480 I807815H593 LEVEL: Error 
 PID : 1860 TID : 2732 PROC : db2syscs.exe 
 INSTANCE: DB2INST NODE : 000 
 MESSAGE : SQLB_OBJECT_DESC 
 DATA #1 : Hexdump, 68 bytes 
 0x04B6B5DC : 2200 0600 2200 0600 0000 0000 003A A2A6 "..."........:.. 
 0x04B6B5EC : 40E5 0000 0000 0000 0000 0000 0000 0000 @............... 
 0x04B6B5FC : 0000 0000 0101 0000 2700 0000 0000 0000 ........'....... 
 0x04B6B60C : 0010 0000 2000 0000 0100 0000 2200 0600 .... ......."... 
 0x04B6B61C : 408C 7400 @.t.

可以从系统表中读取判断是哪个表受到损坏。例如:

select tabname from syscat.tables where tbspaceid=34 and tableid=6

数据库最严重的故障莫过于数据库损坏。从上面的例子来看,我们的数据库中有数据页受到损坏。出现 SQL1034C 错误时,我们首先执行操作系统命令。例如在 AIX 操作系统上,执行“ errpt – d H – T PERM ”命令来判断系统是否出现硬件损坏。然后尝试使用“ db2 restart db sample ”命令让数据库执行崩溃恢复。

如果上述办法不能解决问题,那么最好的办法是从备份恢复数据库。如果无法从备份恢复,那么可以根据损坏的原因尝试相应的解决方案。对于存储问题导致部分数据文件损坏,但是数据库还可以连接的情况,可以采用导出数据库的表结构和数据的方法来恢复数据库。当然对于损坏的表,导出是无法完成的。这时可以使用 db2dart 的导出数据功能来导出这些损坏的表的数据。如果数据库损坏到已经无法连接的程度,那么除了从备份恢复,唯一的办法就是使用 db2dart 来导出所有数据了。下面展示了使用 db2dart 命令时的提示信息:

运行命令 db2dart /DDEL 
   # Table object data formatting start. 
   # Please enter 
   # Table ID or name, tablespace ID, first page, num of pages: 
  # (suffic page number with 'p' for pool relative),

按照提示输入表名、表空间 ID、起始页数、需要导出的页数。如果你的数据库非常大的话,这将是一个工作量非常大的事情。因此建议大家做好数据库备份。

9.1.5  inspect 命令使用案例

inspect 命令类似于 db2dart 命令,它同样可以用来检查数据库、表空间和表。 inspect 命令和 db2dart 命令的主要区别是:inspect 命令需要与数据库连接,并且可以在该数据库上同时有多个活动的数据库连接时执行;而 db2dart 命令在执行之前需要断开所有数据库连接,数据库上不能有活动的数据库连接。

inspect 命令可以在有其他用户连接的情况下验证数据库的完整性。例如,使用“ db2 inspect check database results keep <filename> ”命令可以验证整个数据库的完整性,具体语法如下所示:

db2 " inspect check database results keep inspect.rel " 
 DB20000I  INSPECT 命令成功完成。

在 Windows 平台下,输出文件在“ C:\IBM\SQLLIB\ 实例名”或 DB2INSTPORF 变量指定的目录下;在 Linux/UNIX 平台下,输出文件在“ $INSTHOME/sqllib/db2dump ”目录下。输出的文件需要由 db2instpf 命令进行格式化,db2instpf 命令的语法是:

db2inspf <data file> <out file>

例如:

db2inspf INSPECT.rel INSPECT.out

执行 inspect 命令时还可以加很多参数,使用时可以执行“ db2 ? inspect ”查看详细的命令选项。下面我们举几个 inspect 的使用案例:

例如,如果希望只检查表空间 2 中的数据,可执行以下命令:

db2 "inspect check tablespace tbspaceid 2 results keep inspect.rel" 
 DB20000I  INSPECT 命令成功完成。

对数据库从表空间 11 对象 2 开始执行一致性检查,可执行以下命令:

db2 inspect check database begin TBSPACEID 11 OBJECTID 2 results checkts.out

产生的 checkts.out 报告的具体信息如下所示:

9.2  db2pdcfg

db2pd 是一个新的实用程序,可用来从正在运行的 DB2 实例或数据库中检索统计信息。它类似于 Informix 的 onstat 实用程序。该工具可以提供大量有用信息以帮助进行性能监控、故障诊断和问题确定、性能提高和应用程序开发设计。

db2pd 在执行时不需要获得任何锁存器或使用任何引擎资源就可以收集信息。因此,当 db2pd 收集信息时,有可能会检索到正在更改的信息;这样,数据可能不是十分准确。但是,在不锁内存的情况下收集信息有两个好处:检索速度更快并且不会争用引擎资源。

我们已经在《 DB2 性能调整和优化》和《循序渐进 DB2 —— DBA 系统管理、运维和应用案例》两书中介绍了 db2pd 在性能监控方面的案例,本节我们重点讲解如何利用 db2pdcfg 配置一些选项来影响 db2pd 收集的配置信息。

db2pdcfg 命令的帮助信息如下所示:

C:\>db2pdcfg -h 
 Usage:-catchclear | status | <errorCode> [<action>] [count=<count>] 
 Sets catchflag to catch error or warning. 
 Error Codes: 
 <sqlCode>[,<reasonCode>] / sqlcode=<sqlCode>[,<reasonCode>] 
   ZRC (hex or integer) 
 ZRC #define (such as SQLP_LTIMEOUT) 
 ECF (hex or integer) 
 "deadlock" or "locktimeout" 
 Actions: 
 [stack] (default) Produce stack trace in db2diag.log 
 [DB2COS] (default) Run sqllib/DB2COS callout script 
 [stopDB2TRC]  Stop DB2TRC 
 [dumpcomponent] Dump component flag 
 [component=<componentID>] Component ID 
 [lockname=<lockname>] Lockname for catching specific lock 
 (lockname=000200030000001F0000000052) 
 [locktype=<locktype>] Locktype for catching specific lock 
 (locktype=R or locktype=52)-cos[status] [off] [on]
 [sleep=<numsec>] [timeout=<numsec>] [count=<count>] [SQLO_SIG_DUMP] 
 Sets engine flags to call DB2COS when trapping. 
 [status] Display DB2COS feature status 
 [off] Disable DB2COS feature for engine traps 
 [on] Enable DB2COS feature for engine traps 
 [sleep=<numsec>] Sleep time beteen checking size of output file 
 [timeout=<numsec>] Wait time before assuming script is finished 
 [count=<count>] Times to execute DB2COS for instance during traps 
 [SQLO_SIG_DUMP] Enable DB2COS execution during SQLO_SIG_DUMP 
 -dbmcfg [xml=<0,1>] 
 Sets DBM Config Reserved Bitmap to values 0 (default) or 1 (instance has xml data). 
 -dbcfg [xml=<0,1>] 
 Sets Database Config Reserved Bitmap to values 0 (default) or 1 (database has xml data).
-fodc[status] [reset] [DUMPDIR=<directory>] 
 Changes First Occurrence Data Capture options. 
 [status] Display FODC options status 
 [reset] Reset all the FODC options to their defaults. 
 [DUMPDIR=<directory>] Specifies path where FODC directory will be created. 
Default is db2 diagnostic path

db2pdcfg 主要有 catch、cos、fodc、dbmcfg 和 dbcfg 这几个命令子选项,现在我们分别讲解这些选项的应用。其中 dbmcfg 和 dbcfg 需要内部产品密码,在这里我们不讲解,我们主要讲解 catch、cos 和 fodc 选项。

9.2.1  db2pdcfg -cos 选项

DB2 调出脚本 (db2cos) 输出文件

db2cos 脚本 (DB2 Call Out Script) 是 DB2 V8.2 以后提供给我们用于高级复杂诊断的一个脚本,在 DB2 V8.2 之前,DB2 在故障诊断方面没有什么好的工具,只能查看 db2diag.log 。 DB2 V8.2 之后出现的 db2cos 脚本和 db2pd 结合起来可以为 DBA 提供一个强大的故障诊断工具 ( 注:DB2 在 V9.5 之后的新版本中提供了一个功能强大的性能监控和诊断工具“ db2top ” ) 。默认情况下,当数据库管理器因为应急启动、陷阱、分段违例或异常而不能继续处理时,将会自动调用 db2cos 脚本。每个 db2cos 脚本将调用 db2pd 命令以默认打开方式收集信息。 db2cos 脚本的名称的格式为 db2cos_hang、db2cos_trap 等等。每个脚本的行为方式类似,但 db2cos_hang 有所不同,它是通过 db2fodc 工具调用的。根据 db2cos 脚本中包含的命令,db2cos 输出文件的内容也会有所不同。

默认情况下,db2cos 脚本在“ $DB2HOME/bin ”目录中。在 UNIX 操作系统上,此目录是只读的。可将 db2cos 脚本复制到“ $DB2HOME/adm ”目录,必要时还可在该位置修改该文件。如果 db2cos 脚本在“ $DB2HOME/adm ”目录中,那么会运行该脚本,否则会运行“ $DB2HOME/bin ”目录中的脚本。

db2cos 脚本中的 db2pd 命令收集到的默认信息包括有关操作系统、已安装 DB2 产品的版本和服务级别,数据库管理器和数据库配置的详细信息,以及有关以下各项的状态信息:代理程序、内存池、内存块、应用程序、实用程序、事务、缓冲池、锁定、事务日志、表空间和容器。此外,它还提供有关下列各项的信息:动态、静态和目录高速缓存的状态,表和索引统计信息,恢复状态以及重新优化的 SQL 语句及活动语句列表。如果需要收集进一步的信息,那么只需使用附加命令更新 db2cos 脚本即可。

调用默认 db2cos 脚本时,它将在 DIAGPATH 数据库管理器配置参数指定的目录中生成输出文件。这些文件名为 XXX.YYY.ZZZ.COS.TXT,其中 XXX 是进程标识 (PID),YYY 是线程标识 (TID),而 ZZZ 是数据库分区号 ( 对于单分区数据库则为 000) 。如果存在多线程陷阱,那么会对每个线程单独调用 db2cos 脚本。如果 PID 和 TID 组合多次出现,那么该数据将追加至文件。还会显示时间戳记,所以您可以区分输出的迭代。 Windows 环境下默认 db2cos.bat 的内容如下所示:

setlocal 
 :iterargs 
 if %0. == . goto iterdone 
 if /i %0. == INSTANCE. set INSTANCE=%1 
 if /i %0. == DATABASE. set DATABASE=%1 
 if /i %0. == TIMESTAMP. set TIMESTAMP=%1 
 if /i %0. == APPID. set APPID=%1 
 if /i %0. == PID. set PID=%1 
 if /i %0. == TID. set TID=%1 
 if /i %0. == DBPART. set DBPART=%1 
 if /i %0. == PROBE. set PROBE=%1 
 if /i %0. == FUNCTION. set FUNCTION=%1 
 if /i %0. == REASON. set REASON=%1 
 if /i %0. == DESCRIPTION. set DESCRIPTION=%1 
 if /i %0. == DiAGPATH. set DIAGPATH=%1 
 shift 
 goto iterargs 
 :iterdone 
 if %DATABASE%. == . goto no_database 
 db2pd -db %DATABASE% -inst >> %DIAGPATH%\DB2COS%PID%%TID%.%DBPART% 
 goto exit 
 :no_database 
 db2pd -inst >> %DIAGPATH%\DB2COS%PID%%TID%.%DBPART% 
 :exit

通过上面的脚本我们可以看到,对于数据库级的事件或故障,默认的 db2cos 脚本用“ -db ”和“ -inst ”选项调用 db2pd 。 DBA 用一个 db2pd 调用替换相应的行,该调用收集锁超时分析所需的监视器数据。

查看 db2cos 配置的具体信息,如下所示:

[db2inst1@unixhost ~]$ db2pdcfg -cos status 
 DB2COS is enabled for engine traps. 
 PD Bitmap: 0x1000 ----------------------------------------------- 
 Sleep Time: 3 
 Timeout: 30

根据 db2cos 脚本中指定的命令,db2cos 输出文件将包含不同信息。如果未改变默认脚本,那么 db2diag.log 会显示类似以下的条目:

2008-10-14-10.56.21.523659 
 PID:782348 TID:1 PROC:DB2COS 
实例:db2inst1 节点:0 数据库:SAMPLE 
 APPHDL : APPID: *LOCAL.db2inst1.051014155507 
函数:操作系统服务 , sqloEDUCodeTrapHandler, 探测点:999 
事件:从操作系统服务 sqloEDUCodeTrapHandler 调用
 /home/db2inst1/sqllib/bin/DB2COS 捕获到陷阱
实例 db2inst1 使用 64 位和 DB2 代码发行版 SQL09010 
 ... 
操作系统信息:
操作系统名称:AIX 
节点名:n1 
版本:5 
发行版:2 
机器:000966594C00 
 ----------------------------------- 省略 ---------------------------------- 
 2008-10-14-10.42.17.149512-300 I19441A349 级别:事件
 PID:782348 TID:1 PROC:db2sysc 
实例:db2inst1 节点:000 
函数:DB2 UDB,跟踪服务,pdInvokeCalloutScript,探测点:10 
开始:从操作系统服务 sqloEDUCodeTrapHandler 调用 /home/db2inst1/sqllib/bin/DB2COS 
 2005-10-14-10.42.23.173872-300 I19791A310 级别:事件
 PID:782348 TID:1 PROC:db2sysc 
实例:db2inst1 节点:000 
函数:DB2 UDB,跟踪服务,pdInvokeCalloutScript,探测点:20 
停止:完成 /home/db2inst1/sqllib/bin/DB2COS 调用
 2008-10-14-10.42.23.519227-300 E20102A509 级别:严重
 PID:782348 TID:1 PROC:db2sysc 
实例:db2inst1 节点:000 
函数:DB2 UDB,操作系统服务,sqloEDUCodeTrapHandler,探测点:10 
消息:ADM0503C 发生了意外内部处理错误。已关闭所有与此实例相关联的
 DB2 进程。
 已经记录了诊断信息。有关进一步的帮助,与“ IBM 支持机构”联系。
 2005-10-14-10.42.23.520111-300 E20612A642 级别:严重
 PID:782348 TID:1 PROC:db2sysc 
实例:db2inst1 节点:000 
函数:DB2 UDB,操作系统服务,sqloEDUCodeTrapHandler,探测点:20 
 DATA #1:接收到信号编号,4 字节
 11 
 DATA #2:信号信息,64 字节
 0x0FFFFFFFFFFFD5C0 : 0000 000B 0000 0000 0000 0009 0000 0000 .............. 
 0x0FFFFFFFFFFFD5D0 : 0000 0000 0000 0000 0000 0000 0000 0000 .............. 
 0x0FFFFFFFFFFFD5E0 : 0000 0000 0000 0000 0000 0000 0000 0000 .............. 
 0x0FFFFFFFFFFFD5F0 : 0000 0000 0000 0000 0000 0000 0000 0000 ..............

9.2.2  db2pdcfg-catch 选项

从 DB2 V8.2.2 开始,我们可以使用 db2pdcfg -catch 命令选项来捕获错误信息,然后调用 db2cos 脚本收集出错时的现场信息。该命令的使用语法如下所示:

Usage:
 -catch clear | status | <errorCode> [<action>] [count=<count>] 
 Sets catchFlag to catch error or warning. 
 Error Codes:
 <sqlCode>[,<reasonCode>] / sqlcode=<sqlCode>[,<reasonCode>] 
 ZRC (hex or integer) 
 ECF (hex or integer) 
 "deadlock" or "locktimeout" 
 Actions:
 [DB2COS] (default) Run sqllib/DB2COS callout script 
 [lockname=<lockname>] Lockname for catching specific lock 
 (lockname=000200030000001F0000000052) 
 [locktype=<locktype>] Locktype for catching specific lock 
 (locktype=R or locktype=52)

下面我们通过介绍一个实例来详细讲解如何使用 db2pdcfg -catch 命令获取死锁信息。 如无特殊说明,命令均使用 DB2 实例用户执行。

在下面的示例中,假设 DBA 将数据库锁超时值设为 10 秒,如下所示:

update db cfg for sample using locktimeout 10

为了每当出现锁超时时启动 db2cos 脚本,DBA 调用 db2pdcfg 实用程序,如下所示:

db2pdcfg -catch locktimeout count=1

db2pdcfg -catch 选项指定应该自动导致调用 db2cos 脚本的故障或事件。对于锁超时事件,可以指定字符串 LOCKTIMEOUT 。当然,也可以指定与锁超时相应的 SQL 错误码和原因码,如下所示:

db2pdcfg -catch 911,68 count=1

除了一些字符串值和 SQL 代码之外,db2pdcfg 还接受内部 DB2 错误码。所以,用这种方式可以捕捉很多数据库故障和事件。锁超时事件只是使用 db2pdcfg -catch 和 db2cos 脚本的一个例子。

如果 COUNT 子选项的值为 1,则表明当出现锁超时事件时应该执行 db2cos 脚本。 db2pdcfg 通过以下输出确认错误捕捉的设置,具体信息如下所示:

Error Catch #1 
 Sqlcode:  911-- 注:错误代码
 ReasonCode:  68-- 注:锁超时的原因码
 ZRC:  0 
 ECF:  0 
 Component ID:  0 
 LockName:  Not Set 
 LockType:  Not Set 
 Current Count: 0 
 Max Count:  1 
 Bitmap:  0x661 
 Action:  Error code catch flag enabled 
 Action:  Execute sqllib/DB2COS callout script 
 Action:  Produce stack trace in db2diag.log

db2diag.log 诊断日志中也包括错误捕捉设置。可以使用 db2diag 实用程序 ( 用于检查 db2diag.log 内容的一个有用的实用程序 ) 过滤 db2diag.log 文件,而不必在一个文本编辑器中打开它,如下所示:

db2diag -g funcname:=pdErrorCatch 
 2008-12-18-14.25.25.177000+060 I727480H285 LEVEL: Event 
 PID : 4648 TID : 3948 PROC : db2syscs.exe 
 INSTANCE: DB2 NODE : 000 
 FUNCTION: DB2 UDB, RAS/PD component, pdErrorCatch, probe:30 
 START : Error catch set for ZRC -2146435004

ZRC-2146435004 是用于锁超时的 DB2 内部错误码。可以通过下面的 db2diag 命令调用查看这些错误码极其含义,具体信息如下所示:

db2diag -rc -2146435004 
 Input ZRC string '-2146435004' parsed as 0x80100044 (-2146435004). 
 ZRC value to map: 0x80100044 (-2146435004) 
 V7 Equivalent ZRC value: 0xFFFF8544 (-31420) 
 ZRC class : 
 SQL Error, User Error,... (Class Index: 0) 
 Component: 
 SQLP ; data protection services (Component Index: 16) 
 Reason Code: 
 68 (0x0044) 
 Identifer: 
 SQLP_LTIMEOUT 
 Identifer (without component): 
 SQLZ_RC_LTIMEOUT 
 Description: 
 LockTimeOut - tran rollback Reason code 68 
 Associated information: 
 Sqlcode -911 
 SQL0911N The current transaction has been rolled back because of a deadlock or 
 timeout. Reason code "". 
 Number of sqlca tokens : 1 
 Diaglog message number: 1

我们下面更改 db2cos 脚本,以收集关于锁超时的分析数据,具体信息如下所示:

if %DATABASE%. == . goto no_database 
 db2pd -db %DATABASE% -locks wait -transactions -agents -applications -dynamic 
 >> %DIAGPATH%\DB2COS%PID%%TID%.%DBPART% 
 goto exit

现在,db2cos 脚本已准备好,DBA 可以坐等下一次锁超时事件的发生。

假设用户 A 与 B 之间发生锁等待。由于设置了 LOCKTIMEOUT,因此过了 10 秒 (LOCKTIMEOUT=10) 之后用户 B 的事务被回滚。用户 B 通知 DBA 回滚自己的事务,并且收到 SQL 错误消息– 911 和原因码 68(SQL CODE – 911/REASON CODE 68 =LOCKTIMEOUT) 。于是,DBA 检查通过自动调用 db2cos 脚本收集到的监视器数据。

首先,DBA 用锁超时内部错误码调用 db2diag,以确定锁超时发生的确切时间,具体信息如下所示:

db2diag -g data:=-2146435004 
 2008-12-18-14.27.24.656000+060 I6857H409  LEVEL: Event 
 PID : 2968 TID : 2932  PROC : db2syscs.exe 
 INSTANCE: DB2 NODE : 000 DB : SAMPLE 
 APPHDL : 0-21 APPID: *LOCAL.DB2.061226132544 
 AUTHID : FECHNER 
 FUNCTION: DB2 UDB, lock manager, sqlplnfd, probe:999 
 DATA #1 : <preformatted> 
 Caught rc -2146435004. Dumping stack trace.

db2diag.log 条目显示,在 2008-12-18-14.27.24.656000 时发生了一次锁超时。由于 db2cos 脚本将它的输出写到 %DIAGPATH% 中的 DB2COS%PID%%TID%.%DBPART% 文件中,所以 DBA 有望在实例的诊断路径中找到一个 DB2COS29682932.0 文件:

  • %DIAGPATH% = 实例的诊断路径
  • %PID% = PROCESS ID = 2968( 如 db2diag.log 条目中所示 ) —— 进程 ID
  • %TID% =THREAD ID = 2932( 也显示在 db2diag.log 条目中 ) —— 线程 ID
  • %DBPART% = DATABASE PARTITION = 0( 在一个非分区数据库环境中 )

当 db2cos 文件包含“ db2pd -db sample -locks ”命令时,具体信息如下所示:

捕获到锁定超时
实例 DB2 数据库:SAMPLE 
分区号:0 
 PID:940 
 TID:2136 
函数:sqlplnfd 
组件:锁管理器
探测点:999 
时间戳记:2008-12-18-14.28.04.106000 
 AppID:*LOCAL.DB2... 
 AppHdl:
 ... 
数据库分区 0 -- 数据库 SAMPLE -- 活动 -- 正常运行 0 天 00:06:53 
锁定:
 Address TranHdl Lockname Type Mode Sts Owner Dur HldCnt Att Rlse 
 0x402C6B30 3 00020003000000040000000052 Row ..X W* 3 1 0 0 0x40

仅查找“ W* ”,因为这是经历超时的锁定。当锁定转换为更高级的方式时,也会发生锁定超时。在这种情况下,您只会在输出中见到“ C* ”,而不会见到“ W* ”。但是,在此特定情况下发生了锁定等待。可使用 db2cos 文件中其他的 db2pd 命令选项提供的输出将结果映射至事务、应用程序、代理程序甚至是 SQL 语句。可以缩小输出范围或使用其他命令来收集需要的信息。例如,可以更改 db2pd 命令选项而使用 -locks wait 选项,后一个选项仅输出具有等待状态的锁定。如果需要 -app 和 -agent 选项,那么也可以输入它们。

一旦定位到锁超时的 SQL 语句后,我们就可以利用与锁等待类似的流程步骤来解决。捕捉到锁超时后,DBA 可以通过 -catch clear 选项调用 db2pdcfg 来禁用 db2cos 脚本,具体信息如下所示:

db2pdcfg -catch clear 
 All error catch flag settings cleared.

一旦定位了引起锁等待的语句后,我们就可以根据业务逻辑对该 SQL 语句进行调优和创建合理的索引了。

9.2.3  db2pd -fodc 选项

如果 DB2 实例和数据库发生问题,那么应收集发生问题时的数据。 FODC(First Occurrence Data Capture) 是一个术语,用于描述 DB2 环境中发生问题时应采取的操作。应使用 db2pdcfg 工具设置 db2fodc 注册表变量中的选项,以控制中断期间收集的数据;并使用 db2pdcfg -fodc 来更改 db2fodc 注册表变量选项,这些选项会影响 FODC 的数据采集。

发生应急启动、陷阱、分段违例或异常时,事件顺序如下所示:

(1) 创建陷阱文件

(2) 调用信号处理程序

(3) 调用 db2cos 脚本 ( 取决于启用的 db2cos 设置 )

(4) 在管理通知日志中记录相应条目

(5) 在 db2diag.log 中记录相应条目

db2cos 脚本中的 db2pd 命令收集到的默认信息包括有关操作系统、已安装 DB2 产品的版本和服务级别,数据库管理器和数据库配置的详细信息,以及有关以下各项的状态信息:代理程序、内存池、内存块、应用程序、实用程序、事务、缓冲池、锁定、事务日志、表空间和容器。此外,它还会提供有关下列各项的信息:动态、静态和目录高速缓存的状态,表和索引统计信息,恢复状态以及重新优化的 SQL 语句及活动语句列表。如果需要收集进一步的信息,那么只需使用附加命令更新 db2cos 脚本即可。

调用默认 db2cos 脚本时,它将在 DIAGPATH 数据库管理器配置参数指定的目录中生成输出文件。这些文件名为 XXX.YYY.ZZZ.cos.txt,其中 XXX 是进程标识 (PID),YYY 是线程标识 (TID),而 ZZZ 是数据库分区号 ( 对于单分区数据库则为 000) 。如果存在多线程陷阱,那么会对每个线程单独调用 db2cos 脚本。如果 PID 和 TID 组合多次出现,那么该数据将追加至文件。还会显示时间戳记,所以您可以区分输出的迭代。

9.3  db2trc

9.3.1  db2trc

使用 DB2 时,有时候您可能会碰到一条错误消息,该消息提示您“ get a trace and call IBM Support ” ( 获得跟踪信息并联系 IBM 技术支持代表 )、“ [turn] on trace [and] examine the trace record ” ([ 打开 ] 跟踪 [ 和 ] 检查跟踪记录 ),或者“ contact your technical [support] representative with the following information: problem description, SQLCODE, SQLCA contents (if possible)and trace file (if possible) ” ( 联系您的技术 [ 支持 ] 代表,并提供以下信息:问题描述、SQLCODE、SQLCA 内容 ( 如果有的话 ),以及跟踪文件 ( 如果有的话 )) 。或者,当您向 IBM 技术支持代表报告一个问题时,您就可能被要求执行一次跟踪,以捕捉有关您所在环境的详细信息。

分析重复出现的问题时,DB2 跟踪特别有用,它可以极大地方便 IBM 技术支持代表在 DB2 问题确定方面的工作。那么,究竟什么是跟踪,如何进行跟踪呢?下面我们介绍 DB2 跟踪功能和 db2trc 命令,同时将通过实际的示例展示如何捕捉跟踪信息。

理解 DB2 跟踪

DB2 跟踪实质上是运行跟踪程序时捕捉到的控制流信息 ( 函数和相关参数值 ) 的日志。对于那些 DB2 技术支持代表来说,如果只凭错误消息返回的信息难于解决他们正试图诊断的问题,那么跟踪就非常有用。

可以将跟踪限定到一个特定的组件 ( 例如缓冲池服务 ),这种行为被称作屏蔽 (MASKING) 。通过屏蔽跟踪,有助于减少所捕捉的信息量。当进行跟踪时,应尽量使用最小的场景来再现问题;否则,被捕捉的数据量可能会令人生畏。

注意,在诊断错误时,跟踪信息并不总是有用。例如,在以下情况下,它可能不会捕捉错误状况:

  • 跟踪缓冲区设置得不够大,不足以容纳一组完整的相关跟踪事件。
  • 跟踪没有包括新出现的错误情形。

DB2 跟踪功能是通过 db2trc 命令来控制的,可以用该命令来启动和停止跟踪,以及格式化捕捉到的跟踪信息。

注意:

如果启用 DB2 跟踪功能,则会影响系统的性能。性能下降程度取决于在收集跟踪信息时要使用多少资源。应避免在生产环境中进行跟踪,而且应在 DB2 技术支持代表的指导下使用跟踪功能。

使用 db2trc 命令

您可以使用 db2trc 命令来捕捉跟踪信息,并将该信息格式化成可读的文本。可以在操作系统命令提示符下或者从一个 shell 脚本中发出 db2trc 命令。虽然您可以选择将跟踪信息存储到文件 ( 而不是内存 ),但这样会降低跟踪的速度。不过,如果新出现的问题使您不能将跟踪信息 ( 从内存 ) “转储”到文件中,直接将跟踪信息存储到文件也许是您唯一的选择。具体方法是:在问题出现后,立即转储跟踪信息,然后关闭跟踪,最后按照时间顺序或者按照进程或线程来格式化事件数据。

图 9-1 显示了 db2trc 命令的语法。该命令的选项可以归结为两大类:收集 (COLLECTION) 和解析 (PARSING) 。

图 9-1 db2trc 命令的语法
图9-1 db2trc命令的语法
图9-1 db2trc命令的语法
  • 收集选项包括打开或关闭跟踪,指定跟踪缓冲区大小,指定或更改跟踪选项,转储跟踪信息,以及清除跟踪缓冲区。
  • 解析选项包括按照时间顺序或者按照进程或线程来排序格式化的跟踪记录。

跟踪选项包括以下功能:指定一个 MASK,以捕捉那些能满足指定标准 ( 例如,只捕捉与特定函数或组件相关的记录 ) 的跟踪记录,只跟踪指定的进程和线程组合,以及请求 ( 相关的 ) 时间戳数据。

您可以跟踪 DB2 实例或 DAS 实例。跟踪 DB2 实例是默认行为。

注意,相对于 db2trc 命令的大多数选项,“ -u ”选项是访问命令行帮助的便捷方法。

开始跟踪

理解 db2trc 命令的主要选项的最好方法就是去试一下。下面我们举一个非常简单的示例,该示例使用 DB2 附带的 SAMPLE 数据库。首先,我们打开跟踪功能,同时指定一个 8MB 的跟踪缓冲区。我们使用“ -i ”选项将跟踪信息存放到共享内存 ( 而不是一个文件 ),在这种情况下,当缓冲区被充满时,就立即停止跟踪 ( 另一方面,“ -l ”选项会保留尾部的跟踪记录,当缓冲区被充满时,就会从头覆盖最开始的跟踪记录。这是默认选项 ) 。可以按字节或兆字节来指定缓冲区的大小。为了指定兆字节,可以在值后面附上 M 或 m 。

我们还将指定一个跟踪屏蔽,以限制将被捕捉的跟踪记录的数量。在本例中,我们只跟踪缓冲池服务组件。这可以通过两种方式来实现:我们可以简单地指定“ -m ”选项,后面跟上以双引号括起来的组件名称 (-m "buffer pool services"),也可以在完整的 MASK 语法中指定组件号 ( 在这里是 2) 。跟踪屏蔽有 5 个元素,之间以句号隔开:

  • TYPE:该元素指向跟踪记录类型,包括 ENTRY (1)、EXIT (2)、DATA(3)、ERROR(4) 和 FATAL ERROR(5) 。
  • PRODUCT:DB2 是 PRODUCT3 。
  • COMPONENT:该元素指向一个组件名,例如“ buffer pool services (2) ”。也可以指定组件的简称,例如 SQLB 。
  • FUNCTION:该元素指向一个函数名,例如“ sqlbpfDbheapSize(404) ”。
  • FUNCTION CATEORY:该元素指定被跟踪对象是内部函数 (FNC,0)、组件外部接口 (CEI,2) 还是外部 API(API,3) 。

每个元素可以由一个以逗号分隔开的列表组成,或者由一个用连字符连接的范围组成,或者单独由一项组成。可以用星号来匹配任意值。值可以用它们的名称或相应的编号来指定。若将一个屏蔽设为“ *.*.*.*.* ”,则等于未指定屏蔽。建议您用双引号将跟踪屏蔽括起来,以免操作系统 shell 对星号发生错误判断。

组件和函数名以及它们相关的编号列在一些内部头文件中,这些文件是看不到的。如果您需要找出某些名称或编号,以便设置特定的屏蔽,那么建议您观察格式化输出的一个示例 ( 后面会更详细地谈到 ) 。

我们将指定的最后一个选项是“ -t ”选项,该选项指示跟踪功能捕捉与每条跟踪记录相关的相对时间戳。

现在我们就可以开始跟踪了。我们将发出 db2trc 命令,启动默认的 DB2 实例,清除跟踪缓冲区,连接到 SAMPLE 数据库,将跟踪缓冲区的内容写到一个名为 DMP 的文件中,然后关闭跟踪,如下所示:

db2trc on -i 8m -m "*.*.2.*.*" -t 
 db2start 
 db2trc clear 
 db2 connect to sample 
 db2trc dump dmp 
 db2trc off

关于跟踪缓冲区,需要注意如下几点:

  • 当指定一个缓冲区大小时,该值必须是 2 的幂。例如,如果您请求一个 7MB 的缓冲区,由于只舍不入,这个值变为 4MB 。如果请求一个 8 000 000 字节的缓冲区,这个值经过只舍不入后变为 4 194 304 字节。
  • 缓冲区大小最少也要达到 1MB 。在 Windows 操作系统上,默认缓冲区大小是 8MB ;在基于 UNIX 的系统上,这个值是 4MB 。缓冲区的默认大小和最小值取决于 DB2 的版本,跟踪缓冲区的最大值取决于平台。
  • 由于性能的原因,跟踪功能不允许动态更改跟踪缓冲区的大小。只要共享跟踪缓冲区上附加了一个进程,就不能更改缓冲区的大小。指定不同的缓冲区大小的最好方法是在启动实例之前 ( 也就是在发出 db2start 命令之前 ) 发出 db2trc 命令。
  • 如果是在跟踪共享内存,跟踪缓冲区的大小将控制转储文件的大小。如果是将跟踪信息存储到一个文件,则转储文件的大小只受空余空间和系统所允许的最大文件大小的限制。

格式化跟踪文件

对于我们从内存转储到名为 DMP 的文件中的跟踪,通过使用 db2trc 命令上的一个或两个解析选项,我们可以对其进行解析,或将其格式化为可读的文本。下面展示了每个解析请求的示例,包括返回到标准输出的总结信息。在我们的示例中,跟踪文件比较小,因而不会被截掉一部分。下面的输出还展示了各种输出文件的大小。与预期一样,转储文件 (DMP) 大小约为 8MB,跟 db2trc 命令中指定的缓冲区大小相符。

db2trc format dmp fmt 
 Trace truncated  : NO 
 Trace wrapped : NO 
 Total number of trace records  : 2846 
 Number of trace records formatted  : 2846 
 db2trc flow dmp flw 
 Total number of trace records  : 2846 
 Trace truncated  : NO 
 Trace wrapped : NO 
 Number of trace records formatted : 2771 (pid: 23494 tid 1 node: 0) 
 Number of trace records formatted : 15 (pid: 19834 tid 1 node: 0) 
 Number of trace records formatted : 15 (pid: 28780 tid 1 node: 0) 
 Number of trace records formatted : 15 (pid: 28396 tid 1 node: 0) 
 Number of trace records formatted : 30 (pid: 26332 tid 1 node: 0) 
 ls -l 
 ... 
 -rw-r----- 1 db2inst1 staff  8393432 Aug 20 15:43 dmp 
 -rw-r----- 1 db2inst1 staff  121489 Aug 20 15:44 flw 
 -rw-r----- 1 db2inst1 staff  541845 Aug 20 15:44 fmt 
 ...

“ format ”选项创建一个纯文件跟踪输出文件,在此文件中跟踪记录按照时间顺序出现。下面的输出结果展示了那种输出的一个例子。每个记录代表一个有自己的标识号的跟踪点。跟踪点号按照年月顺序出现在格式化的输出文件中。如果检查第一个记录 ( 跟踪点 1),您将看到它包含了跟踪记录类型 ( “ entry ” )、产品 ( “ DB2 ” )、组件 ( “ buffer pool services ” )、函数 ( “ sqlbGetTotalBufferPoolMemSize ” ),以及函数类别 ( “ cei ” ) 。您应该可以想起,这里的信息与可用于定义屏蔽的元素是相对应的。与这些元素等价的数字也出现在跟踪记录中,例如“ (1.3.2.537.2) ”。如果一个跟踪点碰巧也是一个探测点 (PROBE,一个函数中被显式标识出来的一个精确的位置,对应于 db2diag.log 中 PROBE 输出 ),那么探测点也将包括到这个字符串中 ( 例如跟踪点 4) 。

格式化的跟踪记录还标识出进程 ( “ 23494 ” )、线程 ( “ 1 ” )、同伴进程 ( “ companion process ” )、是否适用 ( “ -1 ” ),以及节点 ( “ 0 ” ) 。因为我们为 db2trc 命令指定了“ -t ”选项,因此输出中还包括相对时间戳。相对时间戳显示自跟踪开始所经历的时间。在这里,整个跟踪用了 361 858 476 纳秒,或者说刚刚超过三分之一秒。

如语法图所示 ( 图 9-1),可以用“ format ”选项来解析与一个或多个特定进程相关的跟踪点,例如“ db2trc format dmp fmt1 -p 19834 ”。

1 entry DB2 UDB buffer pool services sqlbGetTotalBufferPoolMemSize cei 
 (1.3.2.537.2) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 0 
 2 entry DB2 UDB buffer pool services sqlbpfDbheapSize fnc (1.3.2.404.0) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 5659 
 3 entry DB2 UDB buffer pool services sqlbGetBPConfig cei (1.3.2.310.2) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 10319 
 4 data DB2 UDB buffer pool services sqlbGetBPConfig cei (3.3.2.310.2.0) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 11629 probe 0 
 bytes 12 
 Data1  (PD_TYPE_HEXDUMP,4) Hexdump: 
 0000 0000 .... 
 5 exit DB2 UDB buffer pool services sqlbGetBPConfig cei (2.3.2.310.2) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 19329 
 rc = 0 
 6 exit DB2 UDB buffer pool services sqlbpfDbheapSize fnc (2.3.2.404.0) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec 22358 
 rc = 0x000448BC = 280764 
 ... 
 2846 exit DB2 UDB buffer pool services sqlbCheckBPFConsistancy fnc (2.3.2.273.0) 
 pid 23494 tid 1 cpid -1 node 0 sec 0 nsec361858476rc = 0

“ flow ”选项创建一个纯文本跟踪输出文件,在这个文件中,跟踪记录是按进程 (BY PROCESS) 以及时间顺序排序的。它所创建的实际上是一个控制流图。下面显示了这样的一个输出示例。该输出中的信息包括进程、线程、节点号,以及跟踪点号、函数名、跟踪记录类型,在某些情况下还包括探测号。其中一个比较好的特性是,为了清晰起见,每个新的函数项呈锯齿状排列。

同样,如语法图 ( 图 9-1) 所示,还可以用“ flow ”选项来解析与一个或多个特定进程相关的跟踪点,例如“ db2trc flow dmp flw1 -p 19834 ”。

... 
 pid = 19834 tid = 1 node = 0 
 846 sqlbPFPrefetcherEntryPoint entry 
 847 sqlbPFPrefetcherEntryPoint data [probe 0] 
 848 | sqlbPFInitPrefetcher entry 
 849 | sqlbPFInitPrefetcher data [probe 0] 
 850 | | sqlbConnectToSharedMemory entry 
 851 | | sqlbConnectToSharedMemory exit 
 852 | | sqlbInitEDU entry 
 853 | | | sqlbGetBPConfig entry 
 854 | | | sqlbGetBPConfig data [probe 0] 
 855 | | | sqlbGetBPConfig exit 
 856 | | | SqlbFileTbl::SqlbFileTbl entry 
 857 | | | SqlbFileTbl::SqlbFileTbl exit 
 858 | | sqlbInitEDU exit 
 859 | sqlbPFInitPrefetcher exit 
 860 | sqlbpfRemoveFromQ entry 
 ...

db2trc 命令的“ info ”选项返回对与一个特定转储文件相关的跟踪参数的简短总结。如果使用名为 DMP 的转储文件,那么命令“ db2trc info dmp ”的返回信息如下所示:

Marker : @TRACE@ 
 Trace version : 6.0 
 Platform : AIX 
 Build level : s040811 
 maxBufferSize : 8388608 bytes (8 MB) 
 auxBufferSize : 6291456 bytes (6 MB) 
 allocationCount : 2 
 DB2TRCD pid : 0 
 Trace destination : <shared memory buffer> 
 crash : disabled 
 crash runtime passno : 0 
 numSuspended : 0 
 Buffer size : 8388608 bytes (8 MB) 
 Allow buffer to wrap : no 
 Mask  : *.*.2.*.* 
 Timestamps : enabled 
 PID.TID mask : all 
 Fixed data mask #1 : all 
 Fixed data mask #2  : all 
 Max system errors : infinite 
 Treat this rc as sys err: none

其他跟踪选项

db2trc 命令还有其他一些选项 ( 如图 9-1 所示 ),其中包括:

  • -perfcount:性能计数器是一个收集选项,它记录了每个函数被调用的总次数。其相关选项“ -t ”规定需要捕捉花在每个函数上的总时间。性能计数器还支持“ -m ”选项,该选项允许指定一个屏蔽。
  • perffmt:性能跟踪格式化器是一个解析选项,它将包含性能计数器数据的转储文件格式化为可读文本,如下所示:
db2 connect reset 
 db2stop 
 db2trc on -i 8m -perfcount -t -m "*.*.2.*.*" 
 db2start 
 db2trc clear 
 db2 connect to sample 
 db2trc dump dmp1 
 db2trc off 
 db2trc perffmt dmp1 pfmt 
 13 (0 sec, 28978 nanosec) sqlbReducePagesPinned 
 8 (0 sec, 114614 nanosec) sqlbLoadContainerList 
 1 (0 sec, 6309 nanosec) sqlbAllocateBuckets 
 1 (0 sec, 28228 nanosec) sqlbpfCreateQ 
 4 (0 sec, 195840 nanosec) sqlbConnectToSharedMemory 
 ...
  • change:这是一个收集选项,它允许更改正发挥效用的跟踪选项。
  • -resume:这是一个收集选项,它让您恢复某个挂起进程的执行。如果没有启用 -suspend ,则不能恢复挂起程序的执行 ( 请参阅后面的内容 ) 。
  • dump -q:“ -q ( 平静模式 ) ”选项禁止将消息“ Trace has been dumped to file... ”打印到标准输出。
  • stop:这是一个收集选项,它根据需要停止跟踪。这时,所有进程都挂起跟踪,但跟踪缓冲区的内容被保存起来,以便以后转储到文件中。这种动作与“ off ”选项相对,后者完全禁止跟踪功能。
  • -c cpid:该跟踪选项要求只跟踪指定的同伴进程。
  • -rc return-code:该跟踪选项要求将指定的值 ( 必须是一个有符号整数 ) 当作一个系统错误来处理。
  • -e max-sys-errors:该跟踪选项要求在指定的系统错误号出现时立即停止跟踪。
  • -crash point:该跟踪选项要求在指定的跟踪点使进程崩溃。可以这样指定跟踪点:“ product-name. component-short-name. function-name.entry | exit | probe ”。例如:“ DB2.SQLE.sqleFirstConnect.entry ”。 PROBE 元素代表函数中除了入口和退出跟踪点的任意跟踪点。 DB2 V8.2 引入了“ -debug ”选项,作为“ -crash ”的同义词。

注意:

使用“ -crash ”选项时务必小心。

  • -passno i:该跟踪选项要求在崩溃点 (CRASH POINT) 执行了 i 次之后使进程崩溃。
  • -sleep s: 该跟踪选项要求进程休眠 S 秒,而不是崩溃。
  • -signum n : 该跟踪选项要求进程发出信号 n,而不是崩溃。
  • -pause : 该跟踪选项要求进程暂停直到收到信号,而不是崩溃。
  • -suspend : 该跟踪选项要求进程挂起执行,而不是崩溃。
  • -softcrash: 该跟踪选项要求进程中断代理,而不是崩溃。

9.3.2  db2trc 案例 1

DB2 跟踪可用于跟踪客户端上应用程序之下的层。它还可以用于跟踪服务器端。 可以使用带时间戳的 DB2 跟踪来发现网络缓慢的问题。下面是可以在客户端上使用的跟踪:

  • 输入命令“db2trc on -t -f trc.dmp”。
  • 通过从 CLP 运行 SQL 语句重新创建性能问题。
  • 输入命令“db2trc off”。

跟踪被关闭后,在发出 db2trc 命令的路径中将生成一个二进制 DUMP 文件。在这里,这个 DUMP 文件是 TRC.DMP 。为了使该文件可读,必须将其流化 ( “ flw ” ) 和格式化 ( “ fmt ” ) 为 ASCII 文件。使用“fmt -c”将生成一个 DRDA 跟踪,如下所示:

db2trc flw trc.dmp trc.flw 
 db2trc fmt trc.dmp trc.fmt 
 db2trc fmt -c trc.dmp trc_drda.fmt

应该注意的是,这个过程需要与收集 DB2 跟踪 DUMP 文件必须在相同的 DB2 版本补丁级别上执行。流文件 (TRC.FLW) 列出每个进程和线程作出的函数调用。格式文件 (TRC.FMT) 将提供关于每个 DB2 函数的详细信息,顺序与写到跟踪文件的顺序一致。如果 db2trc 是带“-t”选项发出的,那么可以用“-t”选项流化 DUMP 文件,如下所示:

db2trc flw -t trc.dmp trc.flw

上面的命令将创建一个带时间戳的 DB2 跟踪流文件。下面的输出结果是 DB2 跟踪流文件的一个示例。第二列是时间戳,其格式为“ ssss:nnnnnnnnn ”。其中“ ssss ”表示秒,“ nnnnnnnnnn ”表示纳秒。

5572283 1485:587835949 | | | | | sqlccrecv data [probe 120] 
 5572284 1485:587837095 | | | | | | sqlcctcprecv entry 
 5572285 1485:587838001 | | | | | | sqlcctcprecv data [probe 1] 
 5572286 1485:587839212 | | | | | | | tcprecv entry 
 6059823 1570:670189615 | | | | | | | tcprecv data [probe 2] 
 6059824 1570:670198964 | | | | | | |tcprecv exit
6059825 1570:670208194 | | | | | | sqlcctcprecv exit 
 6059826 1570:670211750 | | | | | sqlccrecv data [probe 5] 
 6059827 1570:670213511 | | | | | sqlccrecv exit

DB2 依赖于操作系统应用程序编程接口来执行网络通信。可以将上面的“ tcprecv() ”函数看作“ OS API TCP/IP recv() ”调用的一个包装器。“ recv() ”函数从一个连接套接字接收数据。如上面输出所示,“ tcprecv() ”花了大约 85 秒 (1570 – 1485) 来接收数据。这 85 秒由服务器响应时间和网络时间完成。如果在服务器上从 CLP 执行相同的 SQL 语句花的时间要少得多,那么最值得怀疑的是网络,网络管理员需要进行调查。

9.3.3  db2trc 案例 2

在 AIX 操作系统上,系统原先运行良好,而后用户从 DB2 V8 FP7B 升级到 DB2 V8 FP15,并且把实例从 32 位迁移到 64 位。在该机器上中有 3 个实例,其中一个实例在执行了 db2iupdt 命令后无法连接数据库。该实例中仅有一个数据库。

问题诊断步骤如下:

首先查看 db2diag.log 诊断日志文件:

cd ~/sqllib/db2dump 
 mv db2diag.log db2diag.log.bak 
 <reproduce problem> ——注:重新运行出问题的命令或 SQL 
 vi db2diag.log

得到的错误输出信息具体如下所示:

2007-12-12-20.42.45.029130-360 I1838C472    LEVEL: Warning 
 PID:1593388   TID:1   PROC:db2agent (U88FLAQ) 0 
 INSTANCE: iu88flaq  NODE : 000  DB : U88FLAQ 
 APPHDL: 0-7   APPID: *LOCAL.iu88flaq.071213024245 
 FUNCTION: DB2 UDB, base sys utilities, sqleFirstConnect, probe:15 
 RETCODE : ZRC=0x820F0004=-2112946172=SQLO_MEM_SIZE "Mem Mgt invalid size"DIA8563C 
An invalid memory size was requested.2007-12-12-20.42.45.029814-360 I2311C755   
 LEVEL: Warning 

 PID: 1593388    TID: 1      PROC: db2agent (U88FLAQ) 0 
 INSTANCE: iu88flaq   NODE : 000    DB : U88FLAQ 
 APPHDL: 0-7      APPID: *LOCAL.iu88flaq.071213024245 
 FUNCTION: DB2 UDB, base sys utilities, sqleFirstConnect, probe:16 
 DATA #1 : String, 297 bytes 
 Failed to allocate the desired database shared memory set.Check to make sure 
 the configured DATABASE_MEMORY + overflowdoes not exceed the maximum shared 
 memory on the system. Willattempt to allocate the minimum possible db shared 
 memory size. 
 Desired database shared memory set size is (bytes): 
 DATA #2 : Hexdump, 4 bytes 
 0x2FF13E20 : C601 4000            ..@. 
 ------------------------------ 略 ---------------------------------------- 
 2007-12-12-20.42.45.031566-360 I4206C472    LEVEL: Warning 
 PID: 1593388    TID: 1      PROC: db2agent (U88FLAQ) 0 
 INSTANCE: iu88flaq   NODE : 000    DB: U88FLAQ 
 APPHDL: 0-7      APPID: *LOCAL.iu88flaq.071213024245 
 FUNCTION: DB2 UDB, base sys utilities, sqleFirstConnect, probe:15 
 RETCODE : ZRC=0x820F0004=-2112946172=SQLO_MEM_SIZE "Mem Mgt invalid size" 
    DIA8563C An invalid memory size was requested. 
 2007-12-12-20.42.45.032023-360 I5435C491    LEVEL: Severe 
 PID: 1593388    TID: 1      PROC: db2agent (U88FLAQ) 0 
 INSTANCE: iu88flaq   NODE: 000   DB: U88FLAQ 
 APPHDL: 0-7      APPID: *LOCAL.iu88flaq.071213024245 
 FUNCTION: DB2 UDB, base sys utilities, sqleFirstConnect, probe:17 
 RETCODE : ZRC=0x850F0005=-2062614523=SQLO_NOSEG"No Storage Available for allocation"DIA8305C Memory allocation failure occurred.

尝试分配“ 0xC6014000 ”的内存失败!为什么会产生这样的错误呢?从输出结果中我们看到的 SQLO_MEM_SIZE 和 SQLO_NOSEG 开始分析,此类问题应该是内存段分配问题。执行 db2level 命令,结果发现该实例仍然是 32 位,因此执行“ db2iupdt -w 64 ”命令,将实例升级到 64 位,这个问题就解决了。

可是接下来我们却发现仍然无法连接数据库。于是,查看新产生的 db2diag.log 文件。结果发现这一次报了一个不同的错误信息,如下所示:

2007-12-14-12.15.17.656977-360 I1A1093    LEVEL: Event 
 PID : 1052786    TID: 1   PROC : db2 
 INSTANCE: iu88flaq     NODE : 000 
 FUNCTION: DB2 UDB, RAS/PD component, _pdlogInt, probe:120 
 START : New db2diag.log file 
 DATA #1 : Build Level, 144 bytesInstance "iu88flaq"uses"64" bits 
and DB2 code release"SQL08028"--64 位实例

 ------------------------------ 略 ---------------------------------------- 
 2007-12-14-12.15.17.655334-360 I1095A383   LEVEL: Error 
 PID : 1052786    TID: 1   PROC : db2 
 INSTANCE: iu88flaq     NODE : 000 
 FUNCTION: DB2 UDB, command line process,clp_start_bp, probe:3 
 MESSAGE : CLP frontend unable to get REQUEST queue handle 
 DATA #1 : Hexdump, 4 bytes 
 0x0FFFFFFFFFFFD6C8 : 870F 0042            ...B 
 2007-12-14-12.15.45.546601-360 I1479A383    LEVEL: Error 
 PID : 2765134    TID: 1   PROC : db2 
 INSTANCE: iu88flaq     NODE : 000 
 FUNCTION: DB2 UDB, command line process, clp_start_bp, probe:3 
 MESSAGE : CLP frontend unable to get REQUEST queue handle 
 DATA #1 : Hexdump, 4 bytes 
 0x0FFFFFFFFFFFD688 :870F 0042...B 
 -- 注:使用下面命令查看 870F0042 的含义:
 db2diag – rc 870F0042 
 Input ZRC string '0x870f0042' parsed as 0x870F0042 (-2029060030). 
 ZRC value to map: 0x870F0042 (-2029060030) 

     V7 Equivalent ZRC value: 0xFFFFF642 (-2494) 
 ZRC class :  Global Processing Error (Class Index: 7) 
 Component:  SQLO ; oper system services (Component Index: 15) 
 Reason Code:  66 (0x0042) 
 Identifer:  SQLO_QUE_NOT_EXIST 
 Identifer (without component):  SQLZ_RC_QNOEXS 
 Description:  Queue does not exist 
 Associated information:  Sqlcode – 902 
 SQL0902CA system error (reason code = "" occurred.Subsequent SQL 
 statements cannot be processed. 

  Number of sqlca tokens : 1 

  Diaglog message number: 8558

错误信息告诉我们“ queue doesn't exist ”,首先我们要理解一下这个“ queue doesn't exist ”是什么意思?当我们用“ db2 xxxx ”命令执行特定操作的时候,这个 DB2 是一个可执行程序。这个可执行程序被称作“ frontend process ”。当 DB2 这个进程执行的时候,会隐式地在后台生成一个 db2bp 的进程。这个进程叫做“ db2 backend process ”。所以说,当我们用“ db2 connect to <db> ”这个命令连接数据库的时候,真正与数据库相连接的是其后台的 db2bp 进程。而当连接成功以后,后面所有的比如 select 操作什么的,都是通过 queue 这种 IPC 手段与 db2bp 进程进行通信的。

这里我们得到的错误信息意思是说,当 DB2 前台进程“ frontend process ”想找后台进程“ backend process ”的时候,发现用来通信的 queue 不存在!我们知道既然是 IPC 通信,那“ frontend process ”就不可能只是得到一个 queue 不存在就立刻报错。而实际上是用户在发出 connect 命令后等待了很长时间才返回错误。现在让我们来看看这个后台进程正在做什么,竟然让前台进程等了半天也得不到 queue,前台进程不得不退出说明 queue 不存在了……。下面我们利用 db2trc 命令来跟踪:

db2trc on -t -f db2trc.dmp 
 <reproduce problem> 
 db2trc off 
 db2trc flw -t db2trc.dmp db2trc.flw 
 db2trc fmt db2trc.dmp db2trc.fmt

跟踪出来的 FLW 文件有 40 多 MB,大概 51 万行,别被这 51 万行吓着。我们不全看,查看 TRACE 最关键的就是要知道“你现在正在干什么?”、“想要看什么东西?”。我们现在正在调查“ backend process ”为什么不创建 queue,首先让我们从得到的 db2diag.log 入手。先到 FMT 文件里找 db2diag.log 中出现的错误关键字“ 870F ” ( 不包括引号 ),为什么我们找这个关键字呢?因为这个是 db2diag.log 中返回的错误信息。我们就用它作为搜索条件。搜索后得到了一个 ENTRY, 具体信息如下所示:

2170    data DB2 UDB command line process clp_start_bp fnc (3.3.41.7.0.3) 

    pid 2765134 tid 1 cpid -1 node -1 sec 64 nsec 869465587 probe 3 

    bytes 392 

    Data1     (PD_TYPE_DIAG_LOG_REC,384) Diagnostic log record: 

        2007-12-14-12.15.45.546601-360 I1479A383    LEVEL: Error 

    PID : 2765134    TID: 1   PROC : db2 

    INSTANCE: iu88flaq     NODE : 000 

    FUNCTION: DB2 UDB, command line process, clp_start_bp, probe:3 

    MESSAGE : CLP frontend unable to get REQUEST queue handle 

    DATA #1 : Hexdump, 4 bytes 

    0x0FFFFFFFFFFFD688 : 870F 0042            ...B

从输出结果中我们可以发现 2170 对应着 FLW 文件里的 2170, 然后在这个 ENTRY 里我们看到 CLP_START_BP,顾名思义,就是 CLP 用来开启“ backend process ”的“ function call ”的,也就是说,这个 2170 是在“ frontend process ”中的。

然后回到 FLW 文件,找 2170,具体信息如下所示:

2166    64:869290682 | | | | | | | sqlochgfileptr exit 
 2167    64:869405455 | | | | | | _pdlogInt data [probe 90] 
 2168    64:869450954 | | | | | | | sqlowrite entry 
 2169    64:869464745 | | | | | | | sqlowrite exit 
 2170    64:869465587 | | | clp_start_bp data [probe 3] 
 2171    64:869466392 | | | | | | | sqloclose entry 
 2172    64:869472755 | | | | | | | sqloclose exit 
 2173    64:869479918 | | | | | | _pdlogInt exit 
 2174    64:869480276 | | | | | pdLog exit

我们发现直到 64 秒才跑到 2170,往上看,看看它一直在做什么:我们看到了好多“ OpenMLNQue ”,基本上是一秒钟一个。具体信息如下所示:

1437 22:867813790 | | | | | sqloOpenMLNQue data [probe 1] 
 1438 22:867817987 | | | | | | sqlogkey entry 
 1439 22:867818164 | | | | | | sqlogkey data [probe 1] 
 1440 22:867819491  | | | | | | sqlogkey exit [rc = 0x6F02C86F = 1862453359] 
 1441 22:867823317 | | | | | sqloOpenMLNQue exit [rc = 0x870F0042 = 
 -2029060030 = SQLO_QUE_NOT_EXIST] 
 1442 22:867823675 | | | | | sqlorest entry 
 1443 22:867823869 | | | | | sqlorest data [probe 10] 
 1444 23:867842081 | | | | | sqlorest exit 
 1445 23:867845317 | | | | | sqloOpenMLNQue entry 
 1446 23:867847142 | | | | | sqloOpenMLNQue data [probe 1] 
 1447 23:867850175 | | | | | | sqlogkey entry 
 1448 23:867850525 | | | | | | sqlogkey data [probe 1] 
 1449 23:867852012 | | | | | | sqlogkey exit [rc = 0x6F02C86F = 1862453359] 
 1450 23:867855105 | | | | | sqloOpenMLNQue exit [rc = 0x870F0042 = 
 -2029060030 = SQLO_QUE_NOT_EXIST] 
 1451 23:867855472 | | | | | sqlorest entry 
 1452 23:867855657 | | | | | sqlorest data [probe 10] 
 1453 24:867872812 | | | | | sqlorest exit 
 1454 24:867876195 | | | | | sqloOpenMLNQue entry 
 1455 24:867877582 | | | | | sqloOpenMLNQue data [probe 1] 
 1456 24:867880910 | | | | | | sqlogkey entry 
 1457 24:867881256 | | | | | | sqlogkey data [probe 1] 
 1458 24:867882545 | | | | | | sqlogkey exit [rc = 0x6F02C86F = 1862453359] 
 1459 24:867885558 | | | | | sqloOpenMLNQue exit [rc = 0x870F0042 = 
 -2029060030 = SQLO_QUE_NOT_EXIST]

这说明什么问题呢?“ frontend process ”每秒钟检测一次“ backend process queue ”是不是可用,然后等了一分钟左右发现一直找不到,然后就 TIMEOUT 退出了。不过现在还是不知道“ backend process ”在这段时间干了些什么呀?怎么办?既然我们知道了这个进程是“ frontend process ”,那么“ backend process ”肯定在另外的地方。而且想要知道“ backend process ”在干什么,就要找这 64 秒之前的东西,像那些 100 多秒以后的事情就可以忽略不计了。但是这里可是有 51 万行呢,怎么找?我们知道程序的入口都是 MAIN,所以我们来搜索一下关键字 MAIN,获得的信息如下所示:

826  4:873512436 clp bp main entry 
 7699 152:813841403 | | | | sqeDomainSocketManager::GetShareSocketPair entry 
 7702  152:813842874 | | | | sqeDomainSocketManager::GetShareSocketPair exit 
 7705 152:813844661 | | | | sqeDomainSocketPair::WriteConn entry 
 7706 152:813859956 | | | | sqeDomainSocketPair::WriteConn data [probe 20] 
 7707 152:813860226 | | | | sqeDomainSocketPair::WriteConn exit 
 7759 152:813896576 | | sqeDomainSocketPair::ReadConn entry 
 7767 152:813910788 | | sqeDomainSocketPair::ReadConn data [probe 20] 
 7768 152:813911404 | | sqeDomainSocketPair::ReadConn exit 
 7769 152:813911922 | | sqeDomainSocketManager::FreeShareSocketPair entry 
 7770 152:813912487 | | sqeDomainSocketPair::ClrAsyncRead entry 
 7771 152:813919886 | | sqeDomainSocketPair::ClrAsyncRead exit 
 7772 152:813920518 | | sqeDomainSocketPair::ClrAsyncWrite entry 
 7773 152:813923539 | | sqeDomainSocketPair::ClrAsyncWrite exit 
 7776 152:813924917 | | sqeDomainSocketManager::FreeShareSocketPair exit

除了第一个“ clp_bp_main ”,其他的都是 100 秒之后的事情,不用管,去看第一个。从名字上看起来,“ clp_bp_main ”不就是“ CommandLineProcess_BackendProcess_main ”吗,那也就是后台进程的入口。得到的具体信息如下所示:

pid = 3002686tid = 1 node = 0 
 804 4:867219779 sqloDirectStandardFileDescriptorsToDevNull entry 
 810 4:867250656 | sqloAddOneReservedHandle entry 
 811 4:867265542 | sqloAddOneReservedHandle data [probe 10] 
 812 4:867266195 | sqloAddOneReservedHandle exit 
 813 4:867266457 | sqloAddOneReservedHandle entry 
 814 4:867266882 | sqloAddOneReservedHandle data [probe 10] 
 815 4:867267114 | sqloAddOneReservedHandle exit 
 817 4:867267312 | sqloAddOneReservedHandle entry 
 819 4:867267556 | sqloAddOneReservedHandle data [probe 10] 
 820 4:867268020 | sqloAddOneReservedHandle exit 
 821 4:867268268 sqloDirectStandardFileDescriptorsToDevNull exit 
 826 4:873512436 clp_bp_main entry 
 827 4:873535442 | sqleInitApplicationEnvironment entry 
 828 4:873548871 | | sqloGetEnvInternal entry 
 829 4:873557214 | | | EnvRegGetProfile entry 
 830 4:873558276 | | | EnvRegGetProfile exit 
 831 4:873558815 | | | EnvPrfGetValueByEnumIndex entry 
 832 4:873559169 | | | EnvPrfGetValueByEnumIndex exit [rc = 0x870F0104 = 
 -2029059836 = RC_ENV_NOT_FOUND] 
 833 4:873559409 | | | EnvRegGetProfile entry 
 834 4:873559809 | | | EnvRegGetProfile exit 
 835 4:873560012 | | | EnvPrfGetValueByEnumIndex entry 
 836 4:873560306 | | | EnvPrfGetValueByEnumIndex exit [rc = 0x870F0104 = 
 -2029059836 = RC_ENV_NOT_FOUND] 
 837 4:873560884 | | sqloGetEnvInternal exit [rc = 0x870F0104 = -2029059836 
 = RC_ENV_NOT_FOUND] 
 838 4:873569808 | | sqloxltc_app entry 
 839 4:873571249 | | sqloxltc_app exit 
 840 4:873571666 | | sqleBeginTypedCtxInternal entry

而那个对应的进程 ID3002686 就应该是其“ backend process ”的 PID 了,知道了这个,现在我们能看出,用户发出“ db2 connect to <dbname> ”命令是在 TRACE 开启后 4.8 秒的时候,然后继续往下看,看看后台进程都在干什么。往下翻了大概不到 1000 行,我们突然发现了几个时间戳的“ big jump ”,具体信息如下所示:

1235 4:893112670 | | | | sqloPdbTcpipGetFullHostName entry 
 1236 4:893114440 | | | | | sqloPdbTcpIpResolveHostName entry 
 1237 4:893114912 | | | | | | sqloPdbGetHostByName entry 
 1238 4:893115316 | | | | | | sqloPdbGetHostByName data [probe 7] 
 1462 25:10592207 | | | | | | sqloPdbGetHostByName data [probe 25] 
 1463 25:10594709 | | | | | | sqloPdbGetHostByName exit 
 1464 25:10595152 | | | | | sqloPdbTcpIpResolveHostName exit 
 1465 25:10596028 | | | | sqloPdbTcpipGetFullHostName exit 
 1466 25:10599298 | | | | sqlogmblkEx entry 
 1467 25:10628001 | | | | sqlogmblkEx mbt [Marker:PD_OSS_ALLOCATED_MEMORY] 
 1478 25:10699779 | | | | sqloPdbTcpIpResolveHostName entry 
 1479 25:10700201 | | | | | sqloPdbGetHostByName entry 
 1480 25:10700605 | | | | | sqloPdbGetHostByName data [probe 7] 
 1810 45:128224793 | | | | | sqloPdbGetHostByName data [probe 25] 
 1811 45:128226786 | | | | | sqloPdbGetHostByName exit 
 1812 45:128227114 | | | | sqloPdbTcpIpResolveHostName exit 
 1813 45:128228218 | | | | sqloPdbTcpIpResolveHostName entry 
 1814 45:128229057 | | | | | sqloPdbGetHostByName entry 
 1815 45:128230102 | | | | | sqloPdbGetHostByName data [probe 7] 
 2259 65:245641277 | | | | | sqloPdbGetHostByName data [probe 25] 
 2260 65:245643055 | | | | | sqloPdbGetHostByName exit

从 4 秒跳到 25 秒,然后跳到 45 秒,最后跳到 65 秒。看看这几个大的跳跃 , 具体信息如输出结果 9.43 所示:

1238 4:893115316 | | | | | | sqloPdbGetHostByName data [probe 7] 
 1462 25:10592207 | | | | | | sqloPdbGetHostByName data [probe 25] 
 1480 25:10700605 | | | | | sqloPdbGetHostByName data [probe 7] 
 1810 45:128224793 | | | | | sqloPdbGetHostByName data [probe 25] 
 1815 45:128230102 | | | | | sqloPdbGetHostByName data [probe 7] 
 2259 65:245641277 | | | | | sqloPdbGetHostByName data [probe 25]

都是同样的“ function ”,同样的位置。这个“ function ”是做什么的呢?“ GetHostByName ”是 DNS 地址解析。到这里,读者应该知道出错的原因了吧。可以尝试找到 DB2NODES.CFG 文件,查看 HOSTNAME 的值,然后 PING 一下看看,用了 30 秒才返回第一个数据包。

到现在为止,我们已经找出无法连接数据库的主要原因是因为 DNS 的问题。停了实例,把 DB2NODES.CFG 里面的 HOSTNAME 改成 IP 地址,然后重新连接,这次我们连接成功了。

db2trc 是个非常强大的工具 ( 前提是你要会看那些和天书一样的行号和“ function name ” ),用来解决可以重复出现 / 再现的异常时相当简洁明了 ( 最好有明确的 ERROR CODE,如果没有 ERROR CODE,或者是性能调整问题,那么 db2trc 一点用处也没有,并且发生错误时所作的工作不要过大,比如说 LOAD 就很难用 db2trc 调试,我不希望读者花 N 个小时去读 10 万行以上或者几十 MB 的 FLW 文件 ) 。与其花 10 个小时猜测调试各种可能性,不如花 2 个小时坐下来踏踏实实地读 TRACE 文件。

我个人常把 db2trc 看成是深入学习和了解 DB2 内部的一个工具。

关于 DB2 跟踪输出的查找请注意以下几点:

  • 直接搜索错误代码,从文件的底部往上排查。
  • 直接搜索 XFFF 等系统的内部错误返回代码,这些相关的内部代码可以在“ sqlzrc.h ”或操作系统“ /usr/sys/include/errno.h ”这样的头文件中查找到具体信息。
  • 查找“ sqltfast ”,到了这个地方,跟踪就会将相关的错误直接写到 DB2 的诊断日志,到了这个地方我们可以直接跳转到 DB2 的诊断日志去查找更直接的消息。
  • 如果一个线程或者进程没有任何代码返回或者程序出口信息,那么我们基本可以判断这就是挂起了。
  • 直接查找 ERR 或者 SEVERE 这样的关键词。

9.4  db2_call_stack 和 db2nstck

在 DB2 系统挂起的情况下,如何获取 DB2 进程的运行堆栈信息,以便进一步诊断问题呢?对于 DB2 系统挂起的情况,一方面我们可以通过一些操作系统的命令如 iostat、ps 等来查看 DB2 进程是否在工作;另一方面 DB2 也提供了工具程序 db2nstck 和 db2_call_stack,这两个工具程序可以产生 DB2 进程的运行堆栈信息,我们可以通过间断收集 DB2 进程的堆栈信息来了解 DB2 进程是否在运行。如果 DB2 进程挂起,那么产生的堆栈信息还有助于我们诊断挂起的问题。

在 Windows 操作系统上,db2nstck 用来产生单分区数据库 DB2 进程的运行堆栈信息或者多分区数据库的某一个分区 DB2 进程的堆栈信息。在 Windows 操作系统下,db2nstck 程序会生成一个单独的文件,存放在诊断日志路径下,具体输出如下所示:

C:\IBM\SQLLIB\DB2>db2nstck 
 The stack dump has been saved in the file C:\IBM\SQLLIB\DB2\P3584.000

其中 3584 是 DB2SYSC 的进程 ID,该文件是二进制文件,必须使用 DB2XPRT 命令格式化后才能看。

在 Linux/UNIX 操作系统上,db2_call_stack 会收集所有 DB2 分区的进程堆栈信息。在 Linux/UNIX 操作系统下,db2_call_stack 程序会为每一个 DB2 进程产生一个文件,存放在诊断日志路径下,文件名为“ t<pid>.<nnn> ”,其中“ <pid> ”为进程 ID,“ <nnn> ”为数据库节点号。产生的文件为文本文件,可以直接查看。下面是一个 AIX 操作系统下产生的运行堆栈信息的例子,具体信息如下所示:

*** Start stack traceback *** 
 0xD0309A4C semop + 0x80 
 0x203D0E64 sqloWaitEDUWaitPost + 0x130 
 0x203928CC sqleWaitUntilReactivated__FP13sqle_agent_cbPiPUc + 0x55C 
 0x20391BB4 sqleRunAgent__FPcUl + 0x2DC 
 0x201F5A48 sqloCreateEDU__FPFPcUl_vPcUlP13SQLO_EDU_INFOPl + 0x1BC 
 0x201F5F78 sqloSpawnEDU + 0xD0

db2nstck 和 db2_call_stack 会产生所有 DB2 进程的运行堆栈信息,对于性能会有一定的影响。请在 IBM 技术支持人员的指导下使用该命令。

从 DB2 V8.1 补丁 9 开始,可以使用“ db2pd -stack <pid> ”或者“ db2pd-stacks ”命令来产生运行堆栈信息。该命令在所有 DB2 支持的操作系统上都可以使用。其中“ db2pd -stack <pid> ”会产生特定 DB2 进程的运行堆栈信息。“ db2pd – stacks ”会产生当前实例的所有进程的运行堆栈信息。如果是多分区数据库,那么还可以使用“ db2_all ”命令来执行 db2pd 命令,获取所有分区的 DB2 进程堆栈信息。推荐使用 db2pd 命令来产生进程堆栈信息。

9.5  高级诊断案例

下面我们讲解一个高级诊断案例。在一个实际的客户运行环境中,应用程序在 DB2 中挂起,且状态为“ Commit Active ”。

问题描述:在一个运行于 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 
db2icpsdb2hmon0 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 扫描它所花费的时间大大减少,这个挂起的问题就不再发生了。

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

9.6  小结

本章介绍了 DB2 数据库中几个比较高级的诊断工具。这些工具对诊断 DB2 故障有着不可替代的作用。在检查故障情况和诊断故障原因方面,尤其是对于底层的、一般手段难以处理的故障情况,这几种工具都有着非常好的使用效果。

而且这些工具在很大程度上也能帮助 DBA 了解 DB2 底层的很多信息和技术细节。这对 DBA 技术水平的提升也有着很积极的作用。

总之,对于一个致力于成为优秀 DB2 DBA 的工程师来说,这些工具的掌握是必备的。


相关主题


评论

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

static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=10
Zone=Information Management
ArticleID=407461
ArticleTitle=developerWorks 图书频道: 深入解析 DB2 —— 高级管理、内部体系结构与诊断案例,第 9 章
publish-date=07082009