诊断 DB2 Java 应用程序的性能问题

　2008-09-16 16:29:19　来源：WEB开发网　　　

核心提示：应用程序开发人员和数据库管理员每天面临的一项挑战就是处理性能问题，虽然很多性能问题与数据库服务器有关，诊断 DB2 Java 应用程序的性能问题，但也有一些性能问题与客户机应用程序有关，本文深入分析如何从应用程序客户机的角度诊断和隔离性能问题，那么应该在服务器端运行它，如果它在服务器端运行时挂起，您将学习如何排除使用

应用程序开发人员和数据库管理员每天面临的一项挑战就是处理性能问题。虽然很多性能问题与数据库服务器有关，但也有一些性能问题与客户机应用程序有关。本文深入分析如何从应用程序客户机的角度诊断和隔离性能问题。您将学习如何排除使用 IBM® DB2® for Linux®, UNIX®, and Windows® 数据库的 Java™ 应用程序中出现的性能问题。一旦理解了性能问题的根源所在，离找到解决方案也就不远了。

问题诊断和 DB2 架构简介

本文的目的是帮助应用程序开发人员或数据库管理员排除和诊断在部署 Java 应用程序时可能遇到的常见性能问题。其中包括常见的应用程序开发问题，例如挂起或者响应缓慢。

很好地理解 DB2 架构、DB2 应用程序驱动程序和常见的 DB2 组件，对于有效地排除和诊断 Java 应用程序的问题很重要。DB2 客户端由几个层组成，每个组件都有它自己的跟踪实用程序，用于提供独特的信息，以帮助诊断不同类型的应用程序问题。所以在开始讨论不同的诊断工具之前，我们首先来看看 DB2 的客户机-服务器架构。

图 1 给出了 DB2 在客户端和服务器端使用的软件栈。有两种方法可以连接到 DB2。图 1 中描绘的 Client 1 是最常用的配置。在此，诸如 DB2 Runtime Client 之类的 DB2 客户机是与应用程序一起安装的。DB2 Runtime Client 还包括 Universal JDBC Type 2 driver（也称 JCC T2）。

第二种方法，即图 1 中描绘的 Client 2，不需要安装 DB2 客户机。它不使用 DB2 客户机，而是使用 Universal JDBC Type 4 driver（也称 JCC T4），后者可以单独下载。为了使用 JCC T4 driver，应用程序开发人员必须在应用程序使用的 CLASSPATH 中包括 db2jcc.jar 和许可文件 db2jcc_license_*.jar。这两种类型的客户机都使用一种称作 Distributed Relational Database Architecture™（DRDA®）的开放数据库通信标准与 DB2 数据库服务器通信。

图 1. DB2 客户机/服务器架构

诊断 DB2 Java 应用程序的性能问题 (1)

DB2 客户机提供很多类型的应用程序接口。图 2 显示了应用层，其中详述了可以与 DB2 一起使用的应用程序类型。其中大多数应用程序都通过 DB2 Call Level Interface（CLI）。JCC 驱动程序只限于 Java 应用程序，因为这是一个基于 Java 的应用程序。当出现问题时，取决于使用的应用程序的类型，应用程序开发人员可以收集下面描述的跟踪信息的组合。

Call Level Interface (CLI) Trace：大多数应用程序通过 CLI 层。

DB2 跟踪：在用户应用程序下和在 DRDA 通信层跟踪 DB2 客户端的内部工作情况。也可用于跟踪服务器端的问题。

JCC 跟踪：这是用于使用 DB2 Universal JDBC Driver 的应用程序的一个单独的跟踪实用程序。

JDBC 跟踪：跟踪遗留 JDBC Type 2 driver；但是不常用，因为对这一层的调用将被向下传递到 CLI 层。

图 2. 应用层详图

诊断 DB2 Java 应用程序的性能问题 (1)

下面是在故障诊断时要记住的一些关键概念：

使用自上而下的方法进行故障诊断，而不是盯着细节，试图弄清楚那些细节是否与当前问题有关。

理解环境和配置。

应用程序在哪里运行？

数据库驻留在哪里？

每个系统上使用何种平台、何种操作系统和什么版本（修复包级别）的 DB2？

尽可能地简化环境和应用程序。

从应用程序的外面执行相同的查询是否会表现出相同的行为？

与从客户端运行查询相比，从服务器运行查询是否可以产生相同的响应？

注意最近的任何软件或硬件的变化。

只有在理解了环境并简化了问题域之后，才使用可用的跟踪功能向下探索以发现根本原因。

在客户端和服务器端应用程序以及 DB2 日志中查找相应的消息。

Developer Workbench 调试功能概述

Developer Workbench 提供一个全面的开发环境，为 SQL 和 Java 例程的开发和调试提供了便利。当创建一个存储过程时，应该在调适模式下创建例程。

图 3. 为新的存储过程启用调试

诊断 DB2 Java 应用程序的性能问题 (1)

现在可以在存储过程中创建一些断点，然后单击 Debug 对话框开始调试。

图 4. Debug 对话框

诊断 DB2 Java 应用程序的性能问题 (1)

在下面的屏幕快照中，调试器在每个断点处停下，并显示程序中的变量的当前状态。

图 5. 调试存储过程

诊断 DB2 Java 应用程序的性能问题 (1)

图 6. 调试存储过程

诊断 DB2 Java 应用程序的性能问题 (1)

Developer Workbench 是开发 Java 应用程序的一个方便的工具。但是，当存在性能问题时，应用程序开发人员就可能不知道哪个 Java 例程或哪部分代码的性能有缺陷。DB2 trace 功能可用于向下探索和隔离导致问题的应用程序。

CLI 跟踪概述

IBM Driver for Open Database Connectivity (ODBC) 和 Call Level Interface (CLI) 驱动程序是 DB2 数据库服务器的一个可调用 SQL 接口。JDBC type 2 driver、DB2 Perl module(DBD:DB2)、PHP Data Objects interface for DB2、IBM_DB driver for Ruby on Rails 和 .NET/ADO/OLEDB 提供程序构建在 IBM Driver for Open Database Connectivity (ODBC) 和 Call Level Interface (CLI) 驱动程序之上。

DB2 CLI trace 是 IBM driver for Open Database Connectivity (ODBC) 和 Call Level Interface (CLI) 驱动程序中内建的跟踪功能。所有直接或间接访问 CLI 层的应用程序都可以使用 CLI trace 来跟踪。DB2 CLI trace 包含不同的时间信息，这些信息可用于诊断应用程序的性能问题。

清单 1 中的 CLI trace 为每个 CLI 函数显示一个向外箭头（指向右边）和一个向内箭头（指向左边）。向外箭头显示自上次的 CLI 调用以来在应用程序中花费的时间。向内箭头显示在 DB2 客户机之外花费的时间，包括网络时间（来回）和在 DB2 服务器上花费的时间。例如，SQLExecute() 调用中显示的 1.828213E+001 秒（大约 18 秒）由 SQL 执行时间加上网络时间组成。可以提取出 SQLPrepareW() 语句中的 SELECT 语句，然后在数据库服务器的 DB2 CLP（命令行处理器）上本地运行它。如果在服务器上运行所花的时间要少得多，那么延迟可能是在网络层。

如果在服务器上的运行时间大致相同，那么 DBA 就必须调优服务器和 SQL 语句。

清单 1. SQLExecute() 中的执行时间

SQLPrepareW( hStmt=1:1, pszSqlStr="select * from EMPLOYEE", cbSqlStr=31 ) 　---> Time elapsed - +1.728000E-003 seconds ( StmtOut="select * from EMPLOYEE" ) ... ...　　　　　　　　　　　　　　　　 SQLExecute( hStmt=1:1 )　　　　　　　　　　　　　　　　　　　　　　　　　　　---> Time elapsed - +2.145000E-003 seconds　　　　　　　　　　　　　　 ( Package="SYSSH200　　　　　", Section=4 )　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　sqlccsend( Handle - 186081616 )　　　　　　　　　　　　　　　　　　　　　sqlccsend( ulBytes - 487 )　　　　　　　　　　　　　　　　　　　　　　　　sqlccsend( ) rc - 0, time elasped - +4.500000E-005　　　　　　　　　　　　sqlccrecv( timeout - +0.000000E+000 )　　　　　　　　　　　　　　　　　　sqlccrecv( ulBytes - 34736 ) - rc - 0, time elapsed - +1.823593E+001　 ( Requested Cursor Attributes=3 )　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　 ( Reply Cursor Attributes=524298 )　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　 ( Actual Cursor Attributes=524299 )　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　 SQLExecute( )　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　<--- SQL_SUCCESS　 Time elapsed - +1.828213E+001 seconds

下面的 CLI 跟踪输出显示在 CLI 调用 SQLGetConnectAttr() 和 SQLColAttributesW() 之间在应用程序中花费的时间为 1.260248E+002 大约（126 秒）。换句话说，应用程序中出现了 1.260248E+002 秒的延迟。如果那样的延迟超出了预期，那么应用程序开发人员应该调查应用程序代码。

清单 2. 应用程序中的执行时间

SQLGetConnectAttr( hDbc=0:1, fOption=SQL_ATTR_AUTOCOMMIT, pvParam=&0c53fdf0, 　　cbParamMax=-4, pcbParam=<NULL pointer> ) 　　---> Time elapsed - +1.407000E-003 seconds SQLGetConnectAttr( pvParam=0 ) 　　<--- SQL_SUCCESS　 Time elapsed - +1.160500E-002 seconds SQLColAttributesW( hStmt=1:1, iCol=1, fDescType=SQL_DESC_SCHEMA_NAME, 　　rgbDesc=&0c53fd10, cbDescMax=200, pcbDesc=&0c53fde0, pfDesc=&0c53fdd8 ) 　　---> Time elapsed - +1.260248E+002 seconds 　　sqlccsend( Handle - 186057520 ) 　　sqlccsend( ulBytes - 228 ) 　　sqlccsend( ) rc - 0, time elasped - +8.000000E-006 　　sqlccrecv( timeout - +0.000000E+000 ) 　　sqlccrecv( ulBytes - 4099 ) - rc - 0, time elapsed - +1.311000E-003 SQLColAttributesW( pCharAttribute="MING　　", psCharAttributeByteLen=16 ) 　　<--- SQL_SUCCESS　 Time elapsed - +4.869600E-002 seconds

下面的 CLI 跟踪显示一个连接花费了 5.569619E+001 秒（大约 55 秒）。如果只在连接期间观察到这样的延迟，那么可能是认证延迟的症状。欲了解更多细节，请参阅诊断认证问题小节。

清单 3. SQLDriverConnect() 中的执行时间

SQLDriverConnect( hDbc=0:1, hwnd=0:0, szConnStrIn="DSN=sample;UID=ming; PWD=********;AUTOCOMMIT=0;CONNECTTYPE=1;", cbConnStrIn=-3, szConnStrOut=&0bf9de64, cbConnStrOutMax=256, pcbConnStrOut=&0bf9e044, fDriverCompletion=SQL_DRIVER_NOPROMPT ) ---> Time elapsed - +1.806000E-003 seconds sqlccsend( Handle - 199165312 ) sqlccsend( ulBytes - 276 ) sqlccsend( ) rc - 0, time elasped - +2.440000E-004 sqlccrecv( ) sqlccrecv( ulBytes - 122 ) - rc - 0, time elapsed - +3.849500E-002 sqlccsend( Handle - 199165312 ) sqlccsend( ulBytes - 272 ) sqlccsend( ) rc - 0, time elasped - +2.670000E-004 sqlccrecv( ) sqlccrecv( ulBytes - 249 ) - rc - 0, time elapsed - +4.629900E-002 ( DBMS NAME="DB2/AIX64", Version="08.02.0004", Fixpack="0x23050106" ) ( Application Codepage=1252, Database Codepage=819, Char Send/Recv Codepage=1252, Graphic Send/Recv Codepage=1200 ) SQLDriverConnect( szConnStrOut="DSN=sample;UID=;PWD=********; DBALIAS=DPMP;AUTOCOMMIT=0;CONNECTTYPE=1;", pcbConnStrOut=74 ) <--- SQL_SUCCESS Time elapsed - +5.569619E+001 seconds

当利用 CLI 跟踪调查性能问题时，重要的是使用 CLI 关键字 TRACECOMM，另外还可以选择使用关键字 TRACETIMESTAMP，因为这两个关键字将跟踪额外的时间信息，并将该信息写入到 CLI 跟踪文件中，从而更方便发现跟踪中的延时。

DB2 跟踪功能概述

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 跟踪流文件。清单 4 是 DB2 跟踪流文件的一个示例。第二列是时间戳，其格式为 ssss:nnnnnnnnn。其中 ssss 表示秒，nnnnnnnnnn 表示纳秒。

清单 4. 带时间戳的 DB2 跟踪

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

清单 5 显示如何使用 db2diag 命令解释 DB2 跟踪或 db2diag.log 中的返回码。

清单 5. 解释返回码

E:db2v8BIN>db2diag -rc fffffb95 Input ECF string 'fffffb95' parsed as 0xFFFFFB95 (-1131）。 NOTE: ../sqz/sqlzwhatisrc.C: V7 input ZRC 0xFFFFFB95 (-1131) may translate to V8 ZRC value of 0x83000 B95 (-2097149035) ZRC value to map: 0x83000B95 (-2097149035) V7 Equivalent ZRC value: 0xFFFFBB95 (-17515) ZRC class : Unexpected Operating System error (Class Index: 3) Component: Unknown component (Component Index: 0) Undefined as of DB2 v8.1.14.292; s061108 Attempting to lookup value 0xFFFFFB95 (-1131) as a sqlcode Sqlcode -1131 SQL1131N　DARI (Stored Procedure) process has been terminated abnormally.

DB2 Universal JDBC driver 跟踪概述

当判断在收到错误消息之前已经发生或正在发生的操作、性能问题或挂起时，需要使用 JDBC Universal Driver (JCC) 跟踪。如果没有这种类型的信息，就难以确定应用程序如何进入这种状态。JCC 跟踪应该在包含 Java 应用程序的系统上运行。

JCC 跟踪的头部提供一组有用的环境信息，例如：

操作系统和环境变量。该信息可用于确定我们是否在使用多个版本的 JCC driver 或应用程序库。

应用程序用于连接的 Userid。

JDK 的版本和供应商。确认 JDK 受 DB2 支持。

JCC Driver 级别和使用的 JDBC 属性。

远程 DB2 数据库的版本。

每种 JCC 驱动程序级别对应于一个 DB2 修复包，如表 1（DB2 v8.x）和表 2 （DB2 v9.x）所示。表 3 显示了从一个 JCC 跟踪返回的产品标识。

表 1. DB2 v8 附带的 JCC Driver 版本

JCC 版本	DB2 版本
JCC 1.0	GA（General Availability 或 FixPak 0）
JCC 1.1	FP1
JCC 1.2	FP2
JCC 1.3	FP3
JCC 1.5	FP4
JCC 1.9	FP5
JCC 2.2	FP6
JCC 2.3	FP7
JCC 2.5	FP8
JCC 2.6.80	FP9
JCC 2.7.58	FP10 SYSPLEX routing support introduced
JCC 2.8.46	FP11
JCC 2.9.31	FP12
JCC 2.10.27	FP13
JCC 2.10.52	FP14

表 2. DB2 9 附带的 JCC Driver 版本

JCC 版本	DB2 版本
JCC 3.1.57	GA（General Availability 或 FixPak 0）
JCC 3.2.49	FP1
JCC 3.3.54	FP2
JCC 3.4.65	FP3

表 3. JCC 跟踪的产品版本

数据库产品版本	DB2 平台
SQL08027	DB2 v8.x on Linux/Unix/Windows
SQL09011	DB2 v9.x on Linux/Unix/Windows
DSN07012	DB2 for z-Series (z/OS) v7.x
DSN08015	DB2 for z-Series (z/OS) v8.x
V05R04M00	DB2 for i-Series (AS400) V5R4

从清单 6 中的示例 JCC 跟踪可以看到，JCC Type 4 应用程序在 Solaris 5.8 上以用户 admin 运行，它使用 userid DB2INST1 连接到 DB2 v8 for z/OS (DSN08015) 上的数据库 SAMPLE。

清单 6. 示例 JCC 跟踪

[ibm][db2][jcc] BEGIN TRACE_DRIVER_CONFIGURATION [ibm][db2][jcc]　Driver: IBM DB2 JDBC Universal Driver Architecture 2.10.62 [ibm][db2][jcc] Compatible JRE versions: { 1.3, 1.4, 1.5 } [ibm][db2][jcc] Target server licensing restrictions: { z/OS: enabled; SQLDS: enabled; iSeries: enabled; DB2 for Unix/Windows: enabled; Cloudscape: enabled } [ibm][db2][jcc] Range checking enabled: true [ibm][db2][jcc] Bug check level: 0xff [ibm][db2][jcc] Default fetch size: 64 [ibm][db2][jcc] Default isolation: 2 [ibm][db2][jcc] Collect performance statistics: false [ibm][db2][jcc] No security manager detected. [ibm][db2][jcc] Detected local client host: appserver.ibm.com/9.29.3.3 [ibm][db2][jcc] Access to package sun.io is permitted by security manager. [ibm][db2][jcc] JDBC 1 system property jdbc.drivers = null [ibm][db2][jcc]　Java Runtime Environment version 1.4.2_07 [ibm][db2][jcc] Java Runtime Environment vendor = Sun Microsystems Inc. [ibm][db2][jcc] Java vendor URL = http://java.sun.com/ [ibm][db2][jcc] Java installation directory = /apps/j2re1.4.2_07 [ibm][db2][jcc] Java Virtual Machine specification version = 1.0 [ibm][db2][jcc] Java Virtual Machine specification vendor = Sun Microsystems Inc. [ibm][db2][jcc] Java Virtual Machine specification name = Java Virtual Machine Specification [ibm][db2][jcc] Java Virtual Machine implementation version = 1.4.2_07-b05 [ibm][db2][jcc] Java Virtual Machine implementation vendor = Sun Microsystems Inc. [ibm][db2][jcc] Java Virtual Machine implementation name = Java HotSpot(TM) Server VM [ibm][db2][jcc] Java Runtime Environment specification version = 1.4 [ibm][db2][jcc] Java Runtime Environment specification vendor = Sun Microsystems Inc. [ibm][db2][jcc] Java Runtime Environment specification name = Java Platform API Specification [ibm][db2][jcc] Java class format version number = 48.0 [ibm][db2][jcc] Java class path = :/apps/jakarta-tomcat-5.5.7/common/lib/db2jcc.jar: /apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_license_cisuz.jar: /apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_license_cisuz.jar: /apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_javax.jar: /apps/jakarta-tomcat-5.5.7/bin/bootstrap.jar: /apps/jakarta-tomcat-5.5.7/bin/commons-logging-api.jar [ibm][db2][jcc] Java native library path = /apps/j2re1.4.2_07/lib/sparc/server: /apps/j2re1.4.2_07/lib/sparc:/apps/j2re1.4.2_07/../lib/sparc:/usr/lib [ibm][db2][jcc] Path of extension directory or directories = /apps/j2re1.4.2_07/lib/ext [ibm][db2][jcc]　Operating system name = SunOS [ibm][db2][jcc]　Operating system architecture = sparc [ibm][db2][jcc]　Operating system version = 5.8 [ibm][db2][jcc] File separator ("/" on UNIX) = / [ibm][db2][jcc] Path separator (":" on UNIX) = : [ibm][db2][jcc] User's account name = admin [ibm][db2][jcc] User's home directory = /home/admin [ibm][db2][jcc] User's current working directory = /apps/jakarta-tomcat-5.5.7/bin [ibm][db2][jcc] Loaded global properties file: /apps/jakarta-tomcat-5.5.7/webapps/ivs/WEB-INF/classes/DB2JccConfiguration.properties [ibm][db2][jcc] Loaded by Context ClassLoader: WebappClassLoader ... ... [ibm][db2][jcc] END TRACE_DRIVER_CONFIGURATION [ibm][db2][jcc] BEGIN TRACE_CONNECTS [ibm][db2][jcc] Attempting connection to test.ibm.com:50000/SAMPLE [ibm][db2][jcc] Using properties: { traceFile/tmp/jcctrace.txt, user=DB2INST1, password=********} [ibm][db2][jcc] END TRACE_CONNECTS ... ... [ibm][db2][jcc][Connection@16fa474] BEGIN TRACE_CONNECTS [ibm][db2][jcc][Connection@16fa474]　Successfully connected to server jdbc:db2://test.ibm.com:50000/SAMPLE [ibm][db2][jcc][Connection@16fa474] User: DB2INST1 [ibm][db2][jcc][Connection@16fa474] Database product name: DB2 [ibm][db2][jcc][Connection@16fa474]　Database product version: DSN08015 [ibm][db2][jcc][Connection@16fa474] Driver name: IBM DB2 JDBC Universal Driver Architecture [ibm][db2][jcc][Connection@16fa474] Driver version: 2.10.62 [ibm][db2][jcc][Connection@16fa474] DB2 Application Correlator: G41E4EB2.GA90.C0E39670F334.0000 [ibm][db2][jcc][Connection@16fa474] END TRACE_CONNECTS ...

Java 性能

性能问题通常可以分为两类：间歇性的（intermittent）和非间歇性的（non-intermittent）。间歇性问题难以排除，因为这些问题可能随着工作负载或应用程序运行的时机而在任意时候发生。对于诊断间歇性性能问题，可以使用的一个非常有用的工具是 db2pd -catch。该工具可以设置为执行一个脚本，该脚本用于在返回指定错误消息时收集诊断信息。这种工具的缺点是，它是在错误发生之后才收集信息的。这个工具的一个理想的用途是当数据库服务器达到一个容量阈值时捕捉快照信息。例如，当超过最大 db2agents 数，DB2 不能接受新连接时，应用程序返回 -1224 (SQL1224)。

可以编写一个名为 “db2cos” 的 shell 脚本，其中包含您想要在 DB2 遇到 SQL1224 错误时运行的任何操作系统或 DB2 命令。注意，该脚本必须命名为 db2cos；否则 DB2 不会执行它。

清单 7. 编写 db2cos 脚本

#!/bin/sh # DB2 Callout script to collect information for SQL1224 echo “Collecting information for SQL1224">>db2cos.rpt echo “db2cos script executed at `date`" >>db2cos.rpt db2pd -agents >>db2cos.rpt

清单 8 演示在 shell 脚本完成之后，如何安装调出脚本。如果错误消息与锁有关，则在 db2cos 脚本中还应该收集锁快照。

清单 8. 启用 db2cos

$ cp db2cos /home/db2inst1/sqllib $ db2pd -catch clear all All error catch flag settings cleared. $ db2pd -catch -1224 Input ECF string '-1224' parsed as 0xFFFFFB38 (-1224）。 Error Catch #1 　　　　Sqlcode:　　　　-1224 　　　　ReasonCode:　　 0 　　　　ZRC:　　　　　　0 　　　　ECF:　　　　　　0 　　　　Component ID:　 0 　　　　LockName:　　　 Not Set 　　　　LockType:　　　 Not Set 　　　　Current Count:　0 　　　　Max Count:　　　255 　　　　Bitmap:　　　　 0x461 　　　　Action:　　　　 Error code catch flag enabled 　　　　Action:　　　　 Execute sqllib/db2cos callout script 　　　　Action:　　　　 Produce stack trace in db2diag.log　　　　

可重复的或非间歇性的问题诊断起来要容易得多，因为可以使用跟踪收集更多的诊断信息。 Java 应用程序的性能问题可以分为 4 种类型：

执行慢

挂起

非 DB2 问题

错误消息

通常，上述第 4 类（错误消息）问题最容易诊断，因为有返回的错误消息。在这种情况下，只需根据在客户端上运行的导致错误消息的应用程序的类型收集适当的跟踪。通常，通过查看跟踪就可以得到足够的信息来解决问题。下一节演示如何诊断前三种情况。

Java 例程实现概述

在诊断 Java 例程（可定义为存储过程或用户定义函数）的问题之前，有必要回顾一下 Java 例程是如何调用的。默认情况下，DB2 在 DB2 之外开始一个名为 db2fmp 的进程，以运行隔离的 Java 例程。之所以采取这样的预防性措施，是因为 DB2 要运行应用程序开发人员所编写的未知的代码。如果出现一个异常，最坏的情况只是 db2fmp 进程被终止，而不会使整个数据库停止工作。这种增加的灵活性还可以在劣质的 Java 例程消耗太多的内存或 CPU 时终止它们。如果 Java 例程不加隔离地在 db2agent 中运行，而不是在 db2fmp 进程中运行，那么一个异常就会使整个数据库停止工作。

除了将 Java 例程定义为 FENCED 或 UNFENCED 外，还可以将它们定义为 THREADSAFE 或 NOT THREADSAFE。不同之处在于，THREADSAFE Java 例程是作为 db2fmp 进程中的一个线程运行的。而 NOT THREADSAFE Java 例程在一个单独的 db2fmp 进程中运行。默认情况下，DB2 将 Java 例程创建为 THREADSAFE。由于 db2fmp 进程是使用隔离 userid 运行的，因此它的资源限制由它的用户限制决定。清单 9 显示了如何发现和修改隔离 userid。

清单 9. 修改隔离 userid

/home/db2inst1/sqllib/adm: ls -la .fenced -rw-r--r--　 1 nobody　nobody　　　　　　 0 Jun 20 16:49 .fenced /home/db2inst1/: db2stop SQL1064N　DB2STOP processing was successful. /home/db2inst1/: chown db2fenc1 /home/db2inst1/sqllib/adm/.fenced /home/db2inst1/: db2start SQL1063N　DB2START processing was successful. /home/db2inst1/sqllib/adm: ls -la .fenced -rw-r--r--　 1 db2fenc1　fencgrp　　　　　　 0 Jun 20 16:55 .fenced

当一个应用程序连接到 DB2 时，将有一个或多个 db2agent 进程被分配给这个应用程序，用以运行查询。当应用程序调用一个 Java 例程时，db2agent 和 db2fmp 进程之间的通信通过 Fenced Mode Communication Pool，后者由 DB2 注册表变量 DB2_FMP_COMM_HEAPSZ 决定。 DB2_FMP_COMM_HEAPSZ 的大小将决定可以在一个实例中运行的并发例程的最大数量。图 7 显示了 Java 例程是如何被调用的。

图 7. 调用 Java 例程

诊断 DB2 Java 应用程序的性能问题 (1)

诊断 Java 例程执行慢的问题

如前面图 1 所示，既有客户端组件，也有服务器端组件，两者各由多个层组成。首先要确定问题是在客户端还是服务器端。为了排除是 Developer Workbench 导致问题的可能性，可以从客户端命令行处理器调用该存储过程（如果适用的话），并检查响应时间是否可以接受。

如果响应时间还是比较长，或者与从应用程序中调用这个存储过程的时间差不多，那么可以断定，应用程序不是罪魁祸首。在这种情况下，接下来可以从服务器的命令行处理器调用这个存储过程。如果响应时间较长，那么数据库管理员应该调查服务器端。性能问题可能是由于配置不当、调优问题或者执行例程时优化器使用了不好的访问计划导致的。

如果不是这样，那么我们可以断定性能下降要么是出现在 DB2 客户机代码中，要么是出现在网络上。此时，可以收集一个带时间戳选项的 DB2 跟踪，以确定是哪个函数用了最长的时间才返回。例如，我们是在等 TCP/IP 吗？有些应用程序使用参数占位符调用例程，因此需要收集 JDBC 或 JCC 跟踪，以捕捉输入参数。应用程序端的日志也可能包含这样的信息。

找出慢的存储过程之后，应用程序开发人员应该在 Java 例程中添加调试代码，以判断性能瓶颈出在什么地方。添加调试代码的最容易的方法是将 INSERT 语句添加到 Java 例程中。清单 10 是创建用于存储调试信息的 SP_DEBUG 表的脚本。

清单 10. 创建调试表的 DB2 脚本

connect to sample; create table sp_debug(sp_name varchar(100), time timestamp, trace_point integer, desc varchar(100)); terminate;

清单 11. 将调试信息写到表中

import java.sql.*; import java.io.*; 　 public class TEST_JAVASP3 　 { 　　 public static void tEST_JAVASP3　(int input) throws SQLException, 　　Exception 　　 { 　　int errorCode; 　　Connection dbCon=null; 　　Statement debug_st=null; 　　PreparedStatement pstmt=null; 　　　　　try 　　　{ 　　　　　　　　　// get caller's connection to the database 　　　dbCon = DriverManager.getConnection("jdbc:default:connection"); 　　// Create a statement handle for to execute debug statements 　　debug_st = dbCon.createStatement(); 　　debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3', 　　　　current timestamp, 1,'entry')"); 　　　　　　String query = "INSERT INTO T1 (C1) VALUES (?)"; 　　debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3', 　　　　current timestamp, 2,'prepare')"); 　　　　　　　　pstmt = dbCon.prepareStatement(query); 　　　　pstmt.setInt(1, input); 　　　　pstmt.executeUpdate(); 　　　　　　debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3', 　　　　　current timestamp, 3,'executeUpdate')"); 　　　/* Cause the stored proc to hang if the input value is 11 */ 　　　if( input == 11) 　　　{ 　　　　　while(true);　　　　　} 　　debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3', 　　　　current timestamp, 4,'done if')"); 　　debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3', 　　　　current timestamp, 10,'exit')"); 　　// Cleanup 　　pstmt.close(); 　　debug_st.close(); 　　dbCon.close();　　　　　　}　　　　catch (SQLException sqle) 　　　{ 　　　　errorCode = sqle.getErrorCode(); 　　　　throw new SQLException( errorCode + " FAILED" ); 　　　} 　　　finally 　　　{ 　　　　　if(pstmt !=null) 　　　　　{pstmt.close();} 　　　　　　　　　　if(debug_st !=null) 　　　　　{debug_st.close();} 　　　　　　　　　　if( dbCon != null) 　　{dbCon.close();}　　　　　} 　　} // end finally }

表 4. SP_DEBUG 表的内容

SP_NAME	TIME	TRACEPOINT	DESC
test_javasp3	2007-07-10-19.25.21.436000	1	entry
test_javasp3	2007-07-10-19.25.21.452000	2	prepare
test_javasp3	2007-07-10-19.25.21.452000	3	executeUpdate
test_javasp3	2007-07-10-19.25.21.452000	4	done if
test_javasp3	2007-07-10-19.25.21.452000	10	exit

使用上述方法的优点是，这种方法非常容易实现。缺点是如果没有数据库连接，就不能将调试信息输出到表中。这大概不是问题，因为像这样严重的错误应该已经解决了。表 4 列出了在执行存储过程之后调试表的内容。它在执行的代码旁显示一个时间戳。

另一种方法是修改 Java 例程，使它将调试信息写到一个文件中，如清单 12 所示。在我们的例子中，我们将一个调试参数添加到存储过程定义中，以启用/禁用调试。当添加调试信息时，可能会有额外的开销，所以应用程序开发人员可以选择从 Java 例程的生产版本中删除调试代码。还应注意，与将调试信息插入到一个表中相比，将调试信息写到文件中需要进行更多的调用，因为需要格式化一个 Java 时间戳。默认情况下，Java 时间戳为自 1970 年 1 月 1 日以来的毫秒数。Calendar() 对象用于将时间戳（单位为毫秒）格式化为人类熟悉的格式。对 debugOut.flush()的调用立即将字符缓冲区转储到文件中。在调试挂起问题时，假设没有这个调用，那么如果在字符缓冲区充满之前发生了挂起，就不能将调试输出写到文件。

清单 12. 将调试信息写到文件

import java.sql.*; import java.io.*; import java.util.*; 　 public class TEST_JAVASP2 　 { 　　 public static void tEST_JAVASP2　(int input, int debug) throws SQLException, 　　Exception 　　 { 　　　 int errorCode; 　　　 PrintWriter debugOut=null; 　　　 Calendar cal = null; 　　　　　　　　try 　　　{ 　　　　　if (debug == 1) 　　　　　{ 　　　　　　cal = Calendar.getInstance(); 　　　　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　　　　　　　　// Open debug file 　　　　　　debugOut = new PrintWriter(new FileWriter("sp_debug.txt")); 　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　　　debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 　　　　　　　　+ "tEST_JAVASP2 - entry"); 　　　　　　　　　　　// Need to flush buffer to disk otherwise when troubleshooting hang 　　　　　　// issue the output file will be empty 　　　　　　debugOut.flush(); 　　　　　} 　　　　　　　　　// get caller's connection to the database 　　　Connection con = DriverManager.getConnection("jdbc:default:connection"); 　　　　　　String query = "INSERT INTO T1 (C1) VALUES (?)"; 　　if (debug == 1) 　　　　　{ 　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 　　　　　　+ "tEST_JAVASP2 - preparing query"); 　　　debugOut.flush(); 　　} 　　　　　　PreparedStatement pstmt = con.prepareStatement(query); 　　　　pstmt.setInt(1, input); 　　　　pstmt.executeUpdate(); 　　if (debug == 1) 　　　　　{ 　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 　　　　　　+ "tEST_JAVASP2 - executed query"); 　　　　debugOut.flush(); 　　　} 　　　if( input == 11) 　　　{ 　　　　　for(int i=0;i<10;i++) 　　　　　{ 　　　　　　if (debug == 1) 　　　　　　　　　　{ 　　　　　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　　　　debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND) 　　　　　　　　　+ " " + "tEST_JAVASP2 - loop" + " i="+i); 　　　　　　debugOut.flush(); 　　　　　　} 　　　　　　}　　　　　　　} 　　　　　　if (debug == 1) 　　　　　{ 　　　　cal.setTimeInMillis(System.currentTimeMillis() ); 　　　　debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND) 　　　　　　+ " " + "tEST_JAVASP2 - exit"); 　　　　debugOut.flush(); 　　　　　　　　// Close debug File 　　　　debugOut.close(); 　　　　} 　　　　　　　}　　　　catch (SQLException sqle) 　　　{ 　　　　errorCode = sqle.getErrorCode(); 　　　　throw new SQLException( errorCode + " FAILED" ); 　　　} 　　　finally 　　　{ 　　　　if(debugOut!=null) 　　　　{debugOut.close(); }　　　　　　　　　　}　　　　　　} }

在执行存储过程之后，调试信息被写到纯文本文件 sp_debug.txt 中。可以修改这些例子，以提供附加的调试信息。847 是毫秒数。此外，还有一些更复杂的生成调试信息的方法，例如这个例子，它演示了如何通过创建一个调试调用库来跟踪 SQL 存储过程。

清单 13. sp_debug.txt 的内容

Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - entry Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - preparing query Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - executed query Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=1 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=2 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=3 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=4 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=5 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=6 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=7 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=8 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=9 Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - exit

诊断 Java 存储过程挂起问题

当一个 Java 应用程序或 DB2 Java 例程挂起时，可以生成一个 javacore（也称 javadump）来确定它是在何处挂起的。下面的例子演示如何为一个 Java 例程收集 javacore。

为了启用 javacore，必须设置 IBM JDK 环境。对于不同的平台和使用的不同 IBM JDK，这个设置过程可能略微有些差别。在我们的例子中，我们从一个 JCC 应用程序连接到 DB2 V8.x server on AIX®。

清单 14. 在 AIX 中启用 Javacores

$ export JAVA_DUMP_OPTS="ONINTERRUPT(JAVADUMP),ONANYSIGNAL(JAVADUMP)" $ export IBM_JAVACOREDIR=/db1/j2ma $ db2set DB2ENVLIST="IBM_JAVACOREDIR JAVA_DUMP_OPTS" $ ulimit -a time(seconds)　　　　unlimited file(blocks)　　　　 unlimited data(kbytes)　　　　 131072 stack(kbytes)　　　　32768 memory(kbytes)　　　 32768 coredump(blocks)　　 unlimited nofiles(descriptors) 2000 $ db2stop SQL1064N　DB2STOP processing was successful. $ db2start SQL1063N　DB2START processing was successful.

注意，设置可能稍微有些不同，因为这个例子中使用的 JDK 级别不同于您使用的 JDK 级别。

JAVA_DUMP_OPTS 指定哪些信号会触发 javacore。

IBM_JAVACOREDIR 指定 javacore 文件的位置。

可以使用 DB2ENVLIST 将环境变量传递给 db2fmp 进程，因为 db2start 命令会过滤掉所有不是以 DB2* 或 db2* 开头的用户环境变量。

然后，确认隔离 userid 的 coredump=unlimited，并重新启动实例。

在这个例子中，JCC 应用程序在一个远程 AIX DB2 服务器上调用存储过程 TEST_JAVASP，而这个存储过程挂起，没有返回。首先要做的事是从客户端收集一个 JCC 跟踪，因为我们想知道发送给存储过程的是什么值。也许是一个特定的 Java 值导致挂起。

清单 15. 对存储过程调用的 JCC 跟踪

[jcc][Time:2007-06-20-17:39:29.388][Thread:main][Connection@54a328] prepareStatement (CALL JASON.TEST_JAVASP(?)) called [jcc][Time:2007-06-20-17:39:29.420][Thread:main][Connection@54a328] prepareStatement () returned PreparedStatement@1fc2fb ... ... [jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] executeUpdate () returned -1 [jcc][SystemMonitor:stop] core: 13.378541ms | network: 9.792076ms | server: 0.0ms [jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] setInt (1, 11) called [jcc][SystemMonitor:start] [jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] executeUpdate () called [jcc] [t4][time:2007-06-20-17:39:30.967][thread:main][tracepoint:1][Request.flush] [jcc][t4]　　　　SEND BUFFER: EXCSQLSTT　　　　　　　(ASCII)　　　　　 (EBCDIC) [jcc][t4]　　　　0 1 2 3 4 5 6 7　 8 9 A B C D E F　 0123456789ABCDEF　0123456789ABCDEF [jcc][t4] 0000　 007ED05100010078　200B00442113A5F9　.~.Q...x ..D!...　.=}...........v9 [jcc][t4] 0010　 A281949740404040　4040404040404040　....@@@@@@@@@@@@　samp　　　　　　 [jcc][t4] 0020　 D5E4D3D3C9C44040　4040404040404040　......@@@@@@@@@@　NULLID　　　　　 [jcc][t4] 0030　 4040E2E8E2E2C8F2　F0F0404040404040　@@........@@@@@@　　SYSSH200　　　 [jcc][t4] 0040　 404040405359534C　564C303100010005　@@@@SYSLVL01....　　　...<.<...... [jcc][t4] 0050　 2105F100052111F1　0008211400007FFF　!....!....!.....　..1....1......". [jcc][t4] 0060　 00062141FFFF0006　2140FFFF00052142　..!A....!@....!B　......... ...... jcc][t4] 0070　 040005210E010008　190080000000　　　...!..........　　..............　 [jcc][t4] [jcc][t4]　　　　SEND BUFFER: SQLDTA　　　　　　　　 (ASCII)　　　　　 (EBCDIC) [jcc][t4] 0000　 0024D0030001001E　2412001000100676　.$......$......v　..}............. [jcc][t4] 0010　 D00300040671E4D0　0001000A147A0000　.....q.......z..　}.....U}.....:.. [jcc][t4] 0020　 0000000B　　　　　　　　　　　　　　....　　　　　　　....　　　　　　 [jcc][t4] [jcc][t4] [time:2007-06-20-17:39:30.967][thread:main][tracepoint:101]Request flushed.

从客户端上的 JCC 跟踪可以看到，最近执行的操作是用输入值 11 调用存储过程 JASON.TEST_JAVASP(?) 时执行的 executeUpdate()。DRDA 缓冲区显示，我们在跟踪结束时发送 EXCSQLSTT（执行 SQL 语句）和 SQLDTA（SQL 数据）。由于没有将任何其他内容返回到客户端，因此应该调查服务器端，以确定为什么没有返回任何内容。注意，这里可能需要 DB2 数据库管理员的帮助，因为应用程序开发人员通常没有访问服务器的权限。

在服务器端，有多种方法可以显示应用程序信息，例如使用 db2pd -applications -db sample、 db2 "list applications show detail" 等等。在我们的例子中，我们选择收集应用程序快照，以发现发生了什么事情。在下面的例子中，JCC 应用程序从客户端 IP 地址 10.1.1.123 和端口 2582 进行连接。如果应用程序与 DB2 数据库在相同的系统上，那么 Inbound communication address = *LOCAL.hostname 。为了从快照中识别出应用程序，应用程序开发人员需要知道应用程序的名称、userid 和它所连接到的数据库。

清单 16. 使用快照发现与应用程序关联的 db2agent 的 PID

　　　　　　Application Snapshot Application handle　　　　　　　　　　　　 = 7 Application status　　　　　　　　　　　　 = UOW Executing Status change time　　　　　　　　　　　　 = Not Collected Application code page　　　　　　　　　　　= 819 Application country/region code　　　　　　= 0 DUOW correlation token　　　　　　　　　　 = GA123456.GA16.070622200608 Application name　　　　　　　　　　　　　 = db2jcc_application Application ID　　　　　　　　　　　　　　 = GA123456.GA16.070622200608 Sequence number　　　　　　　　　　　　　　= 0003 TP Monitor client user ID　　　　　　　　　= TP Monitor client workstation name　　　　 = majason1 TP Monitor client application name　　　　 = TP Monitor client accounting string　　　　= Connection request start timestamp　　　　 = 06/22/2007 16:06:08.388356 Connect request completion timestamp　　　 = 06/22/2007 16:06:08.865863 Application idle time　　　　　　　　　　　= Not Collected CONNECT Authorization ID　　　　　　　　　 = J2MA Client login ID　　　　　　　　　　　　　　= J2MA Configuration NNAME of client　　　　　　　= majason1 Client database manager product ID　　　　 = JCC03020 Process ID of client application　　　　　 = 0 Platform of client application　　　　　　 = Unknown via DRDA Communication protocol of client　　　　　 = TCP/IP Inbound communication address　　　　　　　= 10.1.1.123 2582 ... Coordinator agent process or thread ID　　 = 340630 ...

根据快照信息可以发现，PID 340630 就是负责对存储过程的调用的 db2agent 进程。但是，由于这是一个 Java 存储过程，默认情况下它将在一个 db2fmp 进程中作为一个隔离存储过程运行。在 Windows 之类的支持线程的系统上，这将是一个线程 ID。

可以使用 db2pd -fmp 来发现代表 db2agent 执行该存储过程的 db2fmp 进程。从下面的清单中可以看到，db2fmp PID 313092 中的线程 2571 (0xA0B) 正在为 db2agent PID 340630 运行 Java 存储过程。

清单 17. 发现与应用程序关联的 db2fmp 的 PID

/home/j2ma/sqllib/db2dump: db2pd -fmp Database Partition 0 -- Active -- Up 0 days 00:00:30 -- Date 06/27/2007 15:22:43 FMP: Pool Size:　　　 0 Max Pool Size:　 225 Keep FMP:　　　　YES Initialized:　　 YES Trusted Path:　　/home/j2ma/sqllib/function/unfenced Fenced User:　　 j2ma FMP Process: Address　　　　　　FmpPid　　 Bit　 Flags　　　ActiveThrd PooledThrd Active 0x078000000016CEA0 313092　　 64　　0x00000003 1　　　　　0　　　　　No　　 Active Threads: 　 Address　　　　　　FmpPid　　 EduPid　　 ThreadId　　 0x078000000016D020 313092　　 340630　　 2571　　　　 Pooled Threads: 　 Address　　　　　　FmpPid　　 ThreadId　　 No pooled threads.

现在，我们知道哪个 PID 正在运行 db2fmp，如果它消耗太多的资源，我们可以终止它。如果想进一步调查，可以使用 db2pd -stacks 为每个 DB2 进程创建一个 trap 文件。或者，也可以发出 kill -36 313092。对于不同 UNIX 平台，为生成 trap 文件而发送的信号有所不同。

清单 18. 生成的 trap 文件 t313092.000

******************************************* * A db2fmp process received a sigpre　　　* * signal　　　　　　　　　　　　　　　　　* ******************************************* * Master Thread TID: 00000001　　　　　　 * * Waiter Thread TID: 00002314　　　　* * Number of worker threads in process 00000001 * * db2fmp flags 0000000f　　　　　　　　　 * * thread list ***************************** * Thread TID: 00002571　　　　　　　　　　* ******************************************* 8.1.0.128 s061108 SQL08027 timestamp: 2007-06-27-15.39.55.254086 instance name: j2ma.000 EDU name　　 : db2fmp (Java) Signal #36 uname: S:AIX R:2 V:5 M:0009028F4C00 N:panipuri process id: 313092 thread id : 2314 (0x90A) ... ...　 <StackTrace> -------Frame------ ------Function + Offset------ 0x000000000000377C ?unknown + 0x0 0x090000000027B54C _event_sleep + 0x9C 0x090000000027BAB0 _event_wait + 0x60 0x0900000000287A5C _cond_wait_local + 0x308 0x0900000000287FD0 _cond_wait + 0x44 0x0900000000288848 pthread_cond_timedwait + 0x25C 0x09000000192C3478 sqloAppWaitOnSync + 0x19C 0x090000001954DACC sqle<ProcessObjects> timestamp: 2007-06-27-15.39.56.253815 instance name: j2ma.000 EDU name　　 : db2fmp (Java) Signal #36 uname: S:AIX R:2 V:5 M:0009028F4C00 N:panipuri process id: 313092 thread id : 258 (0x102) kthread id : 397831 <StackTrace> -------Frame------ ------Function + Offset------ 0x000000000000377C ?unknown + 0x0 0x0900000000280724 _p_nsleep + 0xC 0x09000000000350B4 nsleep + 0xAC 0x0900000000040964 sleep + 0x58 0x090000001F9E1E50 sysSignalWait + 0x70 0x090000003170283C signalDispatcherThread + 0xE4 0x0900000031703C58 xmExecuteThread + 0x234 0x090000003170852C threadStart + 0x30 0x090000001F9CCEC4 _start + 0x64 0x0900000000271508 _pthread_body + 0xBC </StackTrace>

这些栈提供的信息有限，因为存储过程是独立于 DB2 的、用于运行应用程序开发人员的代码的过程。可以看到，DB2 调用 JVM 来执行 Java 存储过程。进一步诊断应用程序的理想方法是，应用程序开发人员添加调试代码到 Java 存储过程中。另一种方法是为 db2fmp 生成一个 javacore 文件，以提供附加的信息。

由于我们已经启用了 Javacores，并且已经发现了执行存储过程的 db2fmp 进程的 PID，因此现在可以生成一个 javacore。DB2 将把 javacore 文件转储到它的 db2diag.log 中，而不是一个单独的 javacore 文件。必须使用 grep 命令解析 javacore。

清单 19. 生成 javacore 并解析 db2diag.log

$ kill -QUIT <PID of db2fmp> $ grep MESSAGE /home/j2ma/sqllib/db2dump/db2diag.log >javadump.txt

生成 javacore 之后，在 javacore 中搜索 native ID:0xA0B。记住，这是从 db2pd -fmp 输出的线程 id，并从 2571（十进制）转换为 0xA0B（十六进制）。线程 0xA0B 就是那个挂起的执行 Java 存储过程的线程。在我们的应用程序中，它在第 31 行。查看清单 21 中的源代码，它在一个 while(1) 无限循环中。

清单 20.Javacore 文件

MESSAGE : JVMDG303: JVM Requesting Java core file MESSAGE : NULL　　　　　 ----------------------------------------------------------------- MESSAGE : 0SECTION　　　 TITLE subcomponent dump routine MESSAGE : NULL　　　　　 =============================== MESSAGE : 1TISIGINFO　　 signal 3 received MESSAGE : 1TIDATETIME　　Date:　　　　　　　　 2007/06/27 at 15:24:58 MESSAGE : 1TIFILENAME　　Javacore filename:　　/db1/j2ma/javacore313092.1182972298.txt MESSAGE : 0SECTION　　　 XHPI subcomponent dump routine MESSAGE : NULL　　　　　 ============================== MESSAGE : 1XHTIME　　　　Wed Jun 27 15:24:58 2007 MESSAGE : 1XHSIGRECV　　 SIGQUIT received at 0x7cdb02a639e00002 in <unknown>. MESSAGE : 1XHFULLVERSION J2RE 1.4.2 IBM AIX 5L for PowerPC (64 bit JVM) 　　build caix64142-20040917 MESSAGE : NULL　　 ... ... MESSAGE : 1XMTHDINFO　　 All Thread Details MESSAGE : NULL　　　　　 ------------------ MESSAGE : NULL　　　　　 MESSAGE : 2XMFULLTHDDUMP Full thread dump Classic VM (J2RE 1.4.2 IBM AIX 5L for PowerPC (64 bit JVM) build caix64142-20040917, native threads): MESSAGE : 3XMTHREADINFO　　　"Thread-0" (TID:0x7000000000B8B78, sys_thread_t:0x1130B7340, state:R, native ID:0xA0B) prio=5 MESSAGE : 4XESTACKTRACE　　　　　 at TEST_JAVASP.tEST_JAVASP(TEST_JAVASP.java:31) MESSAGE : 3XHNATIVESTACK　　　 Native Stack MESSAGE : NULL　　　　　　　　 ------------ ...

清单 21.存储过程的源代码

1: /* Java stored procedure to insert a value into the database. 2:　* It will hang if it receives the value 11. 3:　* Inputs: input value (integer) 4:　* Ouputs: None 5:　*/ 6: 7: 8:　　import java.sql.*; 9: 10:　 public class TEST_JAVASP 11:　 { 12:　　 public static void tEST_JAVASP　(int input) throws SQLException, 13: 　　Exception 14:　　 { 15:　　　 int errorCode; 16:　 17:　　　try 18:　　　{ 19:　　　　// get caller's connection to the database 20:　　　Connection con = DriverManager.getConnection("jdbc:default:connection"); 21:　　 22:　　　　String query = "INSERT INTO T1 (C1) VALUES (?)"; 23: 24:　　　　PreparedStatement pstmt = con.prepareStatement(query); 25:　　　　pstmt.setInt(1, input); 26:　　　　pstmt.executeUpdate(); 27:　 28:　　　/* Cause the stored proc to not return if input value is 11 */ 29:　　　if( input == 11) 30:　　　{ 31:　　　　while(true); 　　 32:　　　} 33:　　　}　 34:　　　catch (SQLException sqle) 35:　　　{ 36:　　　　errorCode = sqle.getErrorCode(); 37:　　　　throw new SQLException( errorCode + " FAILED" ); 38:　　　} 39:　　} 40:　}

诊断 Java 应用程序的网络问题

清单 22 在下面的环境中执行 JDBC 应用程序。由于某种未知的原因，这个 Java 应用程序好像挂起了。我们来看看是什么问题。

客户端：在 Windows DB2 v9.1 上运行的遗留的 JDBC Type 2 Application

服务器：AIX DB2 v8.x（存储过程在这个系统上）

清单 22. 运行 Java 应用程序

D:java>java CallTestJavaSPT2 sample majason 12345678 URL is: jdbc:db2:p6db Trying to connect using Legacy JDBC T2 driver Connected to database 　　 Inserting value 9 into database... Done inserting value 9 Inserting value 10 into database... Done inserting value 10 Inserting value 11 into database... (Ctrl-C executed from client side after a few seconds since the program above seems to hang and never return.)

首先要做的是收集客户端或者运行该应用程序的系统上的跟踪。从图 1 可以看到，JDBC Type 2 应用程序在到达 DB2 客户端代码之前先经过 DB2 的 CLI 层。因此我们收集一个并发的 CLI、DB2 和 DRDA 跟踪，并且 CLI 和 DB2 跟踪启用时间戳选项。

CLI 跟踪显示，我们正使用一个参数占位符调用 CALL TEST_JAVASP(?) 存储过程。这个存储过程被使用不同的值调用了三次。可以看到，参数占位符 ? 被绑定一次，然后 SQL 语句执行三次，因为在 SQLBindParameter() 之后有三个对 SQLExecute() 的调用。每当 SQLExecute() 被调用时，可以看到用于参数占位符的值。这个值被标记为 iPar（输入参数编号）和 rgbValue （输入参数值）。所以，对于第一次迭代，rgbValue=9，接着是 rgbValue=10，最后是 rgbValue=11，正是在这个地方应用程序挂起。

清单 23. CLI 跟踪，输入值 rgbValue=9

... [1184187845.736027 - 07/11/2007 17:04:05.736027] 　　SQLPrepareW( hStmt=1:1, pszSqlStr="CALL TEST_JAVASP(?)", cbSqlStr=19 ) [1184187845.748055 - 07/11/2007 17:04:05.748055]　　　　---> Time elapsed - +5.700000E-003 seconds [1184187845.752649 - 07/11/2007 17:04:05.752649] ( StmtOut="CALL TEST_JAVASP(?)" ) [1184187845.758786 - 07/11/2007 17:04:05.758786] [1184187845.761948 - 07/11/2007 17:04:05.761948] SQLPrepareW( ) [1184187845.765148 - 07/11/2007 17:04:05.765148]　　　　<--- SQL_SUCCESS　 Time elapsed - +2.912100E-002 seconds [1184187845.768377 - 07/11/2007 17:04:05.768377] SQLNumParams( hStmt=1:1, pcPar=&0007f994) [1184187845.777452 - 07/11/2007 17:04:05.777452]　　　　---> Time elapsed - +3.229000E-003 seconds [1184187845.780470 - 07/11/2007 17:04:05.780470] SQLNumParams( pcPar=1 ) [1184187845.786270 - 07/11/2007 17:04:05.786270]　　　　<--- SQL_SUCCESS　 Time elapsed - +1.789300E-002 seconds [1184187845.802512 - 07/11/2007 17:04:05.802512] SQLBindParameter( hStmt=1:1, iPar=1, 　　fParamType=SQL_PARAM_INPUT, fCType=SQL_C_LONG, fSQLType=SQL_INTEGER, cbColDef=0, 　　　　ibScale=0, rgbValue=&0b7bb808, cbValueMax=4, pcbValue=&0b7bb804 ) [1184187845.835867 - 07/11/2007 17:04:05.835867]　　　　 ---> Time elapsed - +1.624200E-002 seconds [1184187845.839286 - 07/11/2007 17:04:05.839286] SQLBindParameter( ) [1184187845.842363 - 07/11/2007 17:04:05.842363]　　　　 <--- SQL_SUCCESS　 Time elapsed - +3.985100E-002 seconds [1184187845.845624 - 07/11/2007 17:04:05.845624] SQLExecute( hStmt=1:1 ) [1184187845.851609 - 07/11/2007 17:04:05.851609]　　　　---> Time elapsed - +3.261000E-003 seconds [1184187845.854865 - 07/11/2007 17:04:05.854865] 　　( Package="SYSSH200　　　　　", Section=4 ) [1184187845.863376 - 07/11/2007 17:04:05.863376] [1184187845.880312 - 07/11/2007 17:04:05.880312] 　　( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=9, pcbValue=4, piIndicatorPtr=4 ) [1184187845.901568 - 07/11/2007 17:04:05.901568] 　　sqlccsend( Handle - 192938080 ) 　　sqlccsend( ulBytes - 435 ) 　　sqlccsend( ) rc - 0, time elasped - +7.000000E-005 　　sqlccrecv( timeout - +0.000000E+000 ) 　　sqlccrecv( ulBytes - 198 ) - rc - 0, time elapsed - +3.571100E-001 [1184187846.270909 - 07/11/2007 17:04:06.270909] ( return=0 ) [1184187846.277250 - 07/11/2007 17:04:06.277250] [1184187846.280375 - 07/11/2007 17:04:06.280375] ( COMMIT REQUESTED=1 ) [1184187846.286339 - 07/11/2007 17:04:06.286339] 　　sqlccsend( Handle - 192938080 ) 　　sqlccsend( ulBytes - 10 ) 　　sqlccsend( ) rc - 0, time elasped - +6.400000E-005 　　sqlccrecv( timeout - +0.000000E+000 ) 　　sqlccrecv( ulBytes - 54 ) - rc - 0, time elapsed - +4.342000E-003 [1184187846.306069 - 07/11/2007 17:04:06.306069] ( COMMIT REPLY RECEIVED=1 ) [1184187846.312165 - 07/11/2007 17:04:06.312165] [1184187846.315283 - 07/11/2007 17:04:06.315283] SQLExecute( ) [1184187846.318434 - 07/11/2007 17:04:06.318434]　　　　<--- SQL_SUCCESS　 Time elapsed - +4.728100E-001 seconds

清单 24. CLI 跟踪，输入值 rgbValue=10

... [1184187846.369625 - 07/11/2007 17:04:06.369625] SQLExecute( hStmt=1:1 ) [1184187846.375663 - 07/11/2007 17:04:06.375663]　　　　---> Time elapsed - +6.313000E-003 seconds [1184187846.378759 - 07/11/2007 17:04:06.378759] 　　( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=10, pcbValue=4, piIndicatorPtr=4 ) [1184187846.401220 - 07/11/2007 17:04:06.401220] 　　sqlccsend( Handle - 192938080 ) 　　sqlccsend( ulBytes - 157 ) 　　sqlccsend( ) rc - 0, time elasped - +6.700000E-005 　　sqlccrecv( timeout - +0.000000E+000 ) 　　sqlccrecv( ulBytes - 80 ) - rc - 0, time elapsed - +8.489000E-003 [1184187846.422672 - 07/11/2007 17:04:06.422672] ( return=0 ) [1184187846.428435 - 07/11/2007 17:04:06.428435] [1184187846.432088 - 07/11/2007 17:04:06.432088] ( COMMIT REQUESTED=1 ) [1184187846.438348 - 07/11/2007 17:04:06.438348] 　　sqlccsend( Handle - 192938080 ) 　　sqlccsend( ulBytes - 10 ) 　　sqlccsend( ) rc - 0, time elasped - +6.100000E-005 　　sqlccrecv( timeout - +0.000000E+000 ) 　　sqlccrecv( ulBytes - 54 ) - rc - 0, time elapsed - +3.608000E-003 [1184187846.454256 - 07/11/2007 17:04:06.454256] ( COMMIT REPLY RECEIVED=1 ) [1184187846.460343 - 07/11/2007 17:04:06.460343] [1184187846.464846 - 07/11/2007 17:04:06.464846] SQLExecute( ) [1184187846.468118 - 07/11/2007 17:04:06.468118]　　　　<--- SQL_SUCCESS　 Time elapsed - +9.849300E-002 seconds ... ...

清单 25. CLI 跟踪，输入值 rgbValue=11

... [1184187846.519822 - 07/11/2007 17:04:06.519822] SQLExecute( hStmt=1:1 ) [1184187846.526027 - 07/11/2007 17:04:06.526027]　　　　---> Time elapsed - +6.523000E-003 seconds [1184187846.529060 - 07/11/2007 17:04:06.529060] 　　( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=11, pcbValue=4, piIndicatorPtr=4 ) [1184187846.549404 - 07/11/2007 17:04:06.549404] 　　sqlccsend( Handle - 192938080 ) 　　sqlccsend( ulBytes - 157 ) 　　sqlccsend( ) rc - 0, time elasped - +7.100000E-005 　　sqlccrecv( timeout - +0.000000E+000 )

在第三次迭代期间，CLI 跟踪在 SQLExecute() 之后终止。下一步是简化和去掉应用程序。可以创建一个 DB2 脚本来做同样的工作。

清单 26. test.db2

connect to sample user db2inst1 using 12345678; call test_javasp(9); call test_javasp(10); call test_javasp(11); terminate;

在服务器端执行该脚本可以帮助确定问题是在客户端还是服务器端。如果该脚本在客户端运行得很好，那么应该在服务器端运行它。如果它在服务器端运行时挂起，那么需要调查存储过程。