mysql db2 性能_确定DB2 Java应用程序的性能问题

问题确定和DB2体系结构简介

本文的目的是帮助您作为应用程序开发人员或数据库管理员,对您在部署Java应用程序时可能遇到的常见性能问题进行故障排除和诊断。 这些包括常见的应用程序开发问题,例如挂起或响应缓慢。

深入了解DB2体系结构,DB2应用程序驱动程序以及所涉及的常见DB2组件对于有效地对Java应用程序问题进行故障排除和诊断至关重要。 DB2客户端由几层组成,每个组件都有自己的跟踪实用程序,以提供独特的信息来帮助诊断不同类型的应用程序问题。 因此,在开始研究各种诊断工具之前,我们将从研究DB2客户机-服务器体系结构开始。

图1概述了DB2在客户端和服务器端使用的软件堆栈。 有两种方法可以连接到DB2。 图1所示的客户端1是最常用的配置。 这里,该应用程序安装了一个DB2客户机,例如DB2 Runtime Client。 DB2 Runtime Client还包括Universal JDBC Type 2驱动程序(也称为JCC T2)。

第二种方法(在图1中显示为Client 2)不需要安装DB2客户机。 它使用DB2通用JDBC驱动程序(也称为JCC T4)代替DB2客户机,并且可以单独下载。 (请参阅本文“ 相关主题”部分中的链接。)要使用JCC T4驱动程序,应用程序开发人员必须在应用程序使用的CLASSPATH中包括db2jcc.jar和许可证文件db2jcc_license _ *。jar。 两种类型的客户机都使用称为分布式关系数据库体系结构(DRDA®)的开放式数据库通信标准与DB2数据库服务器进行通信。 有关DRDA的更多信息,链接到相关主题

图1. DB2客户端/服务器架构
DB2客户机/服务器体系结构

DB2客户机提供了许多类型的应用程序接口。 图2显示了应用程序层,其中详细说明了可与DB2一起使用的应用程序类型。 这些应用程序中的大多数都通过DB2呼叫级别接口(CLI)。 JCC驱动程序仅限于Java应用程序,因为它是基于Java的驱动程序。 出现问题时,应用程序开发人员可以根据所使用的应用程序的类型来收集以下所述的跟踪信息的组合。

  1. 呼叫级别接口(CLI)跟踪 :大多数应用程序通过CLI层。
  2. DB2跟踪 :跟踪用户应用程序下方和DRDA通信层的DB2客户端的内部工作。 它也可以用于跟踪服务器端问题。
  3. JCC跟踪 :这是使用DB2通用JDBC驱动程序的应用程序的单独跟踪实用程序。
  4. JDBC跟踪 :这将跟踪旧式JDBC Type 2驱动程序; 但是,它并不经常使用,因为对该层的调用将被向下传递到CLI层。
图2.扩展应用程序层
扩展应用层

在进行故障排除时,请记住以下一些关键概念:

  • 使用自上而下的方法进行故障排除,而不是查看详细信息并尝试弄清楚这些详细信息是否与当前问题有关。
  • 了解环境和配置。
    • 应用程序在哪里运行?
    • 数据库在哪里?
    • 每个系统上都有什么平台,操作系统和DB2版本(修订包级别)?
  • 尽可能简化环境和应用程序。
    • 从应用程序外部执行相同的查询是否表现出相同的行为?
    • 与从客户端执行查询相比,从服务器运行查询是否得到相同的响应?
  • 注意最近的软件或硬件更改。
  • 仅在了解环境并简化问题域之后,才能使用可用的跟踪功能进行深入查找以找到根本原因。
  • 在客户端和服务器端应用程序以及DB2日志中查找任何相应的消息。

Developer Workbench调试工具概述

Developer Workbench提供了一个全面的开发环境,可促进SQL和Java例程的开发和调试。 创建存储过程时,请确保以调试模式创建例程。

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

现在,我们可以在存储过程中创建一些断点,然后单击“调试”对话框开始调试。

图4.调试对话框
调试对话框框

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

图5.调试存储过程
调试存储过程1
图6.调试存储过程
调试存储过程2

Developer Workbench是开发Java应用程序时使用的便捷工具。 但是,当出现性能问题时,应用程序开发人员可能无法了解哪个Java例程或代码的哪一部分执行不充分。 DB2跟踪工具可用于向下钻取并隔离引起问题的应用程序。 有关如何使用Developer Workbench的更多详细信息,请参见“ 相关主题”部分。

CLI跟踪概述

用于开放式数据库连接(ODBC)和调用级别接口(CLI)的DB2 IBM驱动程序是DB2数据库服务器的可调用SQL接口驱动程序。 JDBC 2类驱动程序,DB2 Perl模块(DBD:DB2),用于DB2PHP数据对象接口,用于Ruby on Rails的IBM_DB驱动程序以及.NET / ADO / OLEDB提供程序均基于IBM开放数据库连接(ODBC)驱动程序和呼叫层接口(CLI)驱动程序。

DB2 CLI跟踪是内置在IBM驱动程序中的跟踪工具,用于开放式数据库连接(ODBC)和呼叫级别接口(CLI)驱动程序。 可以使用CLI跟踪来跟踪直接和间接访问CLI驱动程序的所有应用程序。 DB2 CLI跟踪包含各种时序信息,可用于诊断应用程序性能问题。

以下链接提供了有关CLI跟踪的更多信息:

清单1中的CLI跟踪显示了每个CLI函数的out箭头(指向右)和in箭头(指向左)。 向外箭头显示自上次CLI调用以来在应用程序中花费的时间。 in箭头显示了在DB2客户机之外花费的时间,包括网络时间(往返)和在DB2服务器上花费的时间。 例如,SQLExecute()调用中显示的1.828213E + 001秒(约18秒)由SQL执行时间加网络时间组成。 可以提取在SQLPrepareW()语句中找到的SELECT语句,然后在数据库服务器的DB2 CLP(命令行处理器)上本地运行它。 如果在服务器上花费的时间少得多,则延迟可能在网络层。 请参阅“ 使用Java应用程序诊断网络问题 ”一节以调查网络问题。 如果在服务器上运行大约需要相同的时间,则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跟踪的更多信息,请参见developerWorks文章DB2基础:DB2 UDB跟踪工具简介

您可以使用带有时间戳记的DB2跟踪来识别慢速网络问题。 以下是可在客户端使用的跟踪说明:

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

有关其他DB2跟踪选项,请参阅参考资料小节中的DB2跟踪语法。

一旦关闭跟踪,将在发出db2trc命令的路径中生成一个二进制转储文件。 在这种情况下,转储文件是trc.dmp,必须对其进行流(flw)并将其格式化(fmt)到ASCII文件,以便使其可读。 使用fmt -c将生成DRDA跟踪。

例如:

  1. db2trc flw trc.dmp trc.flw
  2. db2trc fmt trc.dmp trc.fmt
  3. db2trc fmt -c trc.dmp trc_drda.fmt

应当注意,此过程需要在与收集DB2跟踪转储文件相同的DB2修订包级别上执行。 流文件(trc.flw)列出了每个进程和线程进行的函数调用。 格式文件(trc.fmt)将按写入跟踪文件的顺序提供有关每个DB2函数调用的详细信息。 如果db2trc on是使用-t选项发出的,则可以使用-t选项流转储文件,如下所示。

  1. db2trc flw -t trc.dmp trc.flw

上面的指示信息创建带有时间戳的DB2跟踪流文件。 清单4是DB2跟踪流文件的样本。 第二列是格式为ssss:nnnnnnnnn的时间戳。 其中ssss表示秒,nnnnnnnnnn表示纳秒。

清单4.带时间戳的DB2跟踪
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依靠操作系统(OS)应用程序编程接口(API)来执行网络通信。 您可以将上面的函数tcprecv()视为OS API TCP / IP recv()调用的包装器。 recv()函数从连接的套接字接收数据。 如清单4所示,tcprecv()大约需要85秒(1570-1485)来接收数据。 这85秒是服务器响应时间和网络时间的总和。 如果从服务器上的CLP执行相同SQL语句花费的时间少得多,则主要是怀疑网络速度较慢,网络管理员需要进行调查。

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

清单5.解释返回码
E:\db2v8\BIN>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通用JDBC驱动程序跟踪概述

需要JDBC通用驱动程序(JCC)跟踪来确定在收到错误消息,性能问题或挂起之前已经发生或正在执行的操作。 如果没有此类信息,则很难确定应用程序如何进入此状态。 JCC跟踪应在托管Java应用程序的系统上运行。

有多种方法可以收集JCC跟踪:

JCC跟踪的标题提供了大量有用的环境信息,例如:

  • 操作系统和环境变量。 这可以用来确定我们是否要选择JCC驱动程序或应用程序库的多个版本。
  • 应用程序用来连接的用户ID
  • JDK版本和供应商。 确保DB2支持JDK
  • 使用的JCC驱动程序级别和JDBC属性
  • 远程DB2数据库的版本

每个JCC驱动程序级别都对应于表1 (DB2 v8.x)和表2 (DB2 v9.x)中描述的DB2修订包。 从JCC跟踪返回的产品标识显示在表3中

表1. DB2 v8附带的JCC驱动程序版本
JCC版本 DB2版本
JCC 1.0 GA(常规可用性或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路由支持
JCC 2.8.46 FP11
JCC 2.9.31 FP12
JCC 2.10.27 FP13
JCC 2.10.52 FP14
表2. DB2 9附带的JCC驱动程序版本
JCC版本 DB2版本
JCC 3.1.57 GA(常规可用性或FixPak 0)
JCC 3.2.49 FP1
JCC 3.3.54 FP2
JCC 3.4.65 FP3
表3. JCC跟踪的产品版本
数据库产品版本 DB2平台
SQL08027 Linux / Unix / Windows上的DB2 v8.x
SQL09011 Linux / Unix / Windows上的DB2 v9.x
DSN07012 DB2 for z系列(z / OS)v7.x
DSN08015 DB2 z系列(z / OS)v8.x
V05R04M00 DB2 i系列(AS400)V5R4

清单6中的示例JCC跟踪中,我们可以看到JCC Type 4应用程序以用户admin的身份在Sun Solaris 5.8上运行,并使用用户标识DB2INST1连接到DB2 v8 for z / OS上的数据库SAMPLE(DSN08015)。

清单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性能

性能问题通常可以分为两种类型:间歇性和非间歇性。 间歇性问题很难解决,因为它们可能根据工作量或应用程序时间而随时发生。 要诊断间歇性性能问题,可以使用的一种非常有用的工具是db2pd -catch 。 可以将此工具设置为执行脚本,当返回指定的错误消息时,该脚本可用于收集诊断信息。 缺点是在发生错误后会收集信息。 此工具的一种理想用法是在数据库服务器达到容量阈值时捕获快照信息。 例如,当db2agent的最大数量已超过并且DB2无法接受新连接时,应用程序将返回-1224(SQL1224)。

您可以编写一个名为“ db2cos”的shell脚本,其中包含要在DB2遇到SQL1224错误时要执行的任何操作系统或DB2命令。 请注意,该脚本必须命名为db2cos。 否则,DB2将不会执行它。 有关db2cos的更多信息,请参见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应用程序的性能问题可以分为四种一般类型:

  • 执行缓慢
  • 非DB2问题
  • 错误信息

通常,由于返回了错误消息,因此上述第四种类型(错误消息)最容易诊断。 在这种情况下,根据导致错误消息的客户端执行的应用程序类型,收集适当的跟踪。 查看跟踪通常可以提供足够的信息来解决问题。 下一节将说明如何诊断上述前三种情况。

Java例程实现概述

在诊断可以定义为存储过程(SP)或用户定义函数(UDF)的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进程是使用受防护的用户ID运行的,因此其资源限制将由其用户限制确定。 清单9显示了如何查找和修改受保护的用户ID。

清单9.修改受保护的用户标识
/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进程之间的通信将通过由DB2注册表变量DB2_FMP_COMM_HEAPSZ确定的Fenced Mode通信池。 DB2_FMP_COMM_HEAPSZ的大小确定可以在实例中运行的并发例程的最大数量。 图7说明了如何调用Java例程。

图7.调用Java例程
调用Java例程

诊断Java例程执行缓慢

如先前在图1中看到的,有客户端和服务器端组件,每个组件都由多层组成。 第一项是确定这是客户端还是服务器端的问题。 要排除Developer Workbench引起问题的可能性,请从客户端命令行处理器(如果适用)调用存储过程,并检查响应时间是否可接受。

如果其响应时间很慢或类似于从应用程序调用SP的时间,那么我们可以得出结论,该应用程序不是罪魁祸首。 在这种情况下,请继续从服务器的命令行处理器调用存储过程。 如果响应时间很慢,则数据库管理员应从服务器端进行调查。 性能问题可能是由优化程序在执行例程时使用的配置错误,调整问题或访问计划不正确引起的。

否则,我们可以得出结论,性能下降是在DB2客户机代码中还是在网络中。 此时,我们可以使用timestamp选项收集DB2跟踪,以确定哪个函数返回时间最长。 例如,我们在等待TCP / IP吗? 一些应用程序将使用参数标记来调用例程,因此将需要收集JDBC或JCC跟踪以捕获输入参数。 应用程序端日志也可能包含此信息。

隔离慢的SP后,应用程序开发人员应将调试代码添加到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 时间 示踪点 数据中心
test_javasp3 2007-07-10-19.25.21.436000 1个 条目
test_javasp3 2007-07-10-19.25.21.452000 2 准备
test_javasp3 2007-07-10-19.25.21.452000 3 executeUpdate
test_javasp3 2007-07-10-19.25.21.452000 4 如果完成
test_javasp3 2007-07-10-19.25.21.452000 10 出口

使用上述方法的优点是它很容易实现。 缺点是,如果没有数据库连接,它将无法将调试信息输出到表。 由于这样的严重错误已经解决,因此这可能不会成为问题。 表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。 为Java应用程序生成Javacore更为简单,并且已在《 IBM JDK诊断指南》中进行了说明

必须设置IBM JDK环境以启用javacores。 对于每个平台和所使用的IBM JDK,设置过程略有不同。 在我们的示例中,我们正在从JCC应用程序连接到AIX®上的DB2 V8.x服务器。 请查阅《 IBM JDK诊断指南》以获取每个平台和IBM JDK的详细设置说明。

清单14.在AIX中启用Javacore
$ 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级别将与您的不同。

  • JAVA_DUMP_OPTS指定哪些信号将触发javacore。
  • IBM_JAVACOREDIR指定javacore文件的位置。
  • DB2ENVLIST用于将环境变量传递给db2fmp进程,因为db2start命令过滤掉了所有不以DB2 *或db2 *开头的用户环境变量。

之后,我们确保受防护的用户标识的coredump=unlimited并重新启动实例。

在此示例中,JCC应用程序在挂起且不返回的远程AIX DB2服务器上调用存储过程TEST_JAVASP。 要做的第一件事是从客户端收集JCC跟踪,因为我们想知道向存储过程发送了哪些值。 可能是某个特定的数据值导致挂起。

清单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数据库管理员的帮助。 有关DRDA流程的更多详细信息,请参见“ 相关主题”部分。

在服务器端,有多种显示应用程序信息的方法,例如,使用db2pd -applications -db sampledb2 "list applications show detail"等。在我们的情况下,我们选择收集应用程序快照以找出什么是发生。 在下面的示例中,JCC应用程序从客户端IP地址10.1.1.123端口2582连接。如果应用程序与DB2数据库位于同一系统上,则入站通信地址= * LOCAL.hostname 。 为了从快照中识别应用程序,应用程序开发人员将需要知道应用程序名称,用户ID和它要连接的数据库。

清单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进程创建一个陷阱文件。 或者,我们可以发出kill -36 313092 。 每个UNIX平台之间发送来生成信息性陷阱文件的信号都不同。

清单18.生成的陷阱文件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 SP。 理想情况下,要进一步诊断,应用程序开发人员应在其Java SP中添加调试代码。 一种替代方法是为db2fmp进程生成一个javacore文件,以提供其他信息。

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

清单19.生成javacore并解析db2diag.log
$ kill -QUIT <PID of db2fmp>
$ grep MESSAGE /home/j2ma/sqllib/db2dump/db2diag.log >javadump.txt

生成javacore后,在javacore中搜索本机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应用程序

服务器: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;

在服务器端执行脚本将有助于将问题隔离到客户端或服务器端问题。 如果脚本在客户端运行良好,则应在服务器端运行。 如果它在服务器端挂起,则需要检查存储过程。

对于我们的示例,假设脚本在服务器端运行良好,但在客户端失败。 由于脚本无法在客户端上运行,因此我们可以排除应用程序层的任何问题,即JDBC到DB2 CLI的接口,因为DB2 CLP绕过了应用程序层。 我们也可以排除服务器端。

再次参考图1 。 我们看到在应用程序层下面是DB2客户机和DRDA通信层。 因此,我们将通过检查DB2和DRDA跟踪来继续研究这两层的网络延迟。 任何其他可能的问题都应由DB2技术支持进行审查。

打开DRDA跟踪,并找到要使用输入参数发送CALL TEST_JAVASP(?)的跟踪点。 我们可以看到输入值的每次迭代都对应于它自己的DB2跟踪点。 在跟踪点49130上的FDODTA = 9,在跟踪点50460上的FDODTA = 10,最后在跟踪点51714上的FDODTA = 11。请注意,在DRDA术语中,AR(应用程序请求者)是客户端,而AS(应用程序服务器)是服务器。 可以在“ 相关主题”部分中找到有关在客户端和服务器之间发送的DRDA流的更多信息。

清单27. CALL TEST_JAVASP(9)的DRDA跟踪
49130	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223545 nsec 574400066 probe 1177
	bytes 452

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 35  CORR: 0003  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLSTT - SQL Statement
      LL: 29    CP: 2414   
      DATA:                              (ASCII)          (EBCDIC)
      000000001343414C 4C20544553545F4A  .....CALL TEST_J .......<<.....^[
      4156415350283F29 FF                AVASP(?).        ....&....
 ...
 ...
   SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0004  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        000009000000                       ......           ......

我们看到SEND(AR),它是来自客户端的发送缓冲区。 SQLDTA(SQL DATA结构)说,我们在CALL TEST_JAVASP(?)中输入9作为参数标记

清单28. CALL TEST_JAVASP(10)的DRDA跟踪
50460	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223546 nsec 533380764 probe 1177
	bytes 174

	SEND BUFFER(AR):

            EXCSQLSTT RQSDSS                 (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0079D05100010073 200B004421135341   .y.Q...s ..D!.SA  .`}.............
  0010  4D504C4520202020 2020202020202020   MPLE              (&<.............
  0020  4E554C4C49442020 2020202020202020   NULLID            +.<<............
  0030  2020535953534832 3030202020202020     SYSSH200        ................
  0040  202020205359534C 564C303100040005       SYSLVL01....  .......<.<......
  0050  2105F100052111F1 0008211400007FFF   !....!....!.....  ..1....1......".
  0060  00062141FFFF0006 2140FFFF00052142   ..!A....!@....!B  ......... ......
  0070  C000081900800000 00                 .........         {........

            SQLDTA OBJDSS                    (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0024D0030001001E 2412001000100676   .$......$......v  ..}.............
  0010  D00300040671E4D0 0001000A147A0000   .....q.......z..  }.....U}.....:..
  0020  0A000000                            ....              ....

  SEND(AR) RQSDSS - Request Data Stream Structure
  LL: 121  CORR: 0001  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: y  

    NM: EXCSQLSTT - Execute SQL Statement
      LL: 115    CP: 200B   
      NM: PKGNAMCSN - RDB Pkg Name, Const Tkn & Sec Num
        LL: 68    CP: 2113   
        * RDBNAM - Relational Database Name
          ASCII: SAMPLE            
          EBCDIC: ..(&<.............
        * RDBCOLID - RDB Collection Identifier
          ASCII: NULLID            
          EBCDIC: +.<<..............
        * PKGID - RDB Package Identifier
          ASCII: SYSSH200          
          EBCDIC: ..................
        * PKGCNSTKN - RDB Package Consistency Token
          DATA:                              (ASCII)          (EBCDIC)
          5359534C564C3031                   SYSLVL01         ...<.<..
        * PKGSN - RDB Package Section Number
          DECIMAL:     4
          HEXADECIMAL: 0004
      NM: RDBCMTOK - RDB Commit Allowed
        LL: 5    CP: 2105   
        BOOLEAN: TRUE
      NM: OUTEXP - Output Expected
        LL: 5    CP: 2111   
        BOOLEAN: TRUE
      NM: QRYBLKSZ - Query Block Size
        LL: 8    CP: 2114   
        DECIMAL:     32767
        HEXADECIMAL: 00007FFF
      NM: MAXBLKEXT - Maximum Number of Extra Blocks
        LL: 6    CP: 2141   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: MAXRSLCNT - Maximum Result Set Count
        LL: 6    CP: 2140   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: RSLSETFLG - Result Set Flags
        LL: 5    CP: 2142   
        FLAG: 0XC0Return Names, Return Labels, 
      NM: MONITOR - Monitor
        LL: 8    CP: 1900   
        DECIMAL:     -2147483648
        HEXADECIMAL: 80000000

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0001  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        00000A000000                       ......           ......

现在是10(十进制)或0xA(十六进制)。 从带有时间戳的相应流文件(trace.flw)中,我们可以看到我们调用了sqlcctcpsend(),它是操作系统的TCP / IP API的包装器,用于发送数据。 此发送花了不到1秒的时间。 如果存在网络延迟,则应在此处显示。

清单29. trace.flw
50480         33:650976401   | | | | | clientCommCallback exit
50481         33:650984989   | | | | sqljcSend exit
50482         33:650989272   | | | | sqljrRecv entry
50483         33:650989982   | | | | | sqljcReceive entry
50484         33:650993253   | | | | | | clientCommCallback entry
50485         33:651003619   | | | | | | | CLI_utlGetInfo entry
50486         33:651005423   | | | | | | | CLI_utlGetInfo exit
50487         33:651008072   | | | | | | | sqlrxf2a entry
50488         33:651021647   | | | | | | | sqlrxf2a data [probe 4]
50489         33:651022705   | | | | | | | sqlrxf2a exit
50490         33:656536851   | | | | | | clientCommCallback exit
50491         33:656547857   | | | | | | sqlccrecv entry
50492         33:656549136   | | | | | | sqlccrecv data [probe 1]
50493         33:656551339   | | | | | | sqlccrecv data [probe 2]
50494         33:656551992   | | | | | | sqlccrecv data [probe 3]
50495         33:656552653   | | | | | | sqlccrecv data [probe 4]
50496         33:656553245   | | | | | | sqlccrecv data [probe 120]
50497         33:656554490   | | | | | | sqlccrecv data [probe 130]
50498         33:656556542   | | | | | | | sqlcctcprecv entry
50499         33:656557298   | | | | | | | sqlcctcprecv data [probe 1]
50500         33:656561269   | | | | | | | |  tcprecv entry 
50501         33:237234851   | | | | | | | | tcprecv data [probe 2] 
50502         33:237247868   | | | | | | | |  tcprecv exit 
50503         33:237256312   | | | | | | | sqlcctcprecv exit
50504         33:237258748   | | | | | | sqlccrecv data [probe 5]
50505         33:237259658   | | | | | | sqlccrecv exit
清单30. CALL TEST_JAVASP(11)的DRDA跟踪
51714	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223546 nsec 816354478 probe 1177
	bytes 174

	SEND BUFFER(AR):

            EXCSQLSTT RQSDSS                 (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0079D05100010073 200B004421135341   .y.Q...s ..D!.SA  .`}.............
  0010  4D504C4520202020 2020202020202020   MPLE              (&<.............
  0020  4E554C4C49442020 2020202020202020   NULLID            +.<<............
  0030  2020535953534832 3030202020202020     SYSSH200        ................
  0040  202020205359534C 564C303100040005       SYSLVL01....  .......<.<......
  0050  2105F100052111F1 0008211400007FFF   !....!....!.....  ..1....1......".
  0060  00062141FFFF0006 2140FFFF00052142   ..!A....!@....!B  ......... ......
  0070  C000081900800000 00                 .........         {........

            SQLDTA OBJDSS                    (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0024D0030001001E 2412001000100676   .$......$......v  ..}.............
  0010  D00300040671E4D0 0001000A147A0000   .....q.......z..  }.....U}.....:..
  0020  0B000000                            ....              ....

  SEND(AR) RQSDSS - Request Data Stream Structure
  LL: 121  CORR: 0001  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: y  

    NM: EXCSQLSTT - Execute SQL Statement
      LL: 115    CP: 200B   
      NM: PKGNAMCSN - RDB Pkg Name, Const Tkn & Sec Num
        LL: 68    CP: 2113   
        * RDBNAM - Relational Database Name
          ASCII: SAMPLE            
          EBCDIC: ..(&<.............
        * RDBCOLID - RDB Collection Identifier
          ASCII: NULLID            
          EBCDIC: +.<<..............
        * PKGID - RDB Package Identifier
          ASCII: SYSSH200          
          EBCDIC: ..................
        * PKGCNSTKN - RDB Package Consistency Token
          DATA:                              (ASCII)          (EBCDIC)
          5359534C564C3031                   SYSLVL01         ...<.<..
        * PKGSN - RDB Package Section Number
          DECIMAL:     4
          HEXADECIMAL: 0004
      NM: RDBCMTOK - RDB Commit Allowed
        LL: 5    CP: 2105   
        BOOLEAN: TRUE
      NM: OUTEXP - Output Expected
        LL: 5    CP: 2111   
        BOOLEAN: TRUE
      NM: QRYBLKSZ - Query Block Size
        LL: 8    CP: 2114   
        DECIMAL:     32767
        HEXADECIMAL: 00007FFF
      NM: MAXBLKEXT - Maximum Number of Extra Blocks
        LL: 6    CP: 2141   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: MAXRSLCNT - Maximum Result Set Count
        LL: 6    CP: 2140   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: RSLSETFLG - Result Set Flags
        LL: 5    CP: 2142   
        FLAG: 0XC0Return Names, Return Labels, 
      NM: MONITOR - Monitor
        LL: 8    CP: 1900   
        DECIMAL:     -2147483648
        HEXADECIMAL: 80000000

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0001  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        00000B000000                       ......           ......

在最后一次迭代( 清单30 )中,当使用11(十进制)或B(十六进制)调用存储过程时,我们在DRDA跟踪中找到跟踪点51714,它对应于流文件中的同一跟踪点。 在内部,我们看到已执行发送,但是在tcprecv()(TCP / IP接收)期间,跟踪点51754和51755之间存在〜7s的延迟。这表明该问题是DB2的外部问题,应由网络管理员调查。 问题可能出在客户端和服务器之间的操作系统的TCP / IP堆栈或网络设备(即防火墙,负载平衡设备,路由器等)中。

清单31. trace.flw
51714         33:922051842   | | | | sqljcSend data [probe 1177]
...
51735         33:934285388   | | | | sqljcSend exit
51736         33:934290007   | | | | sqljrRecv entry
51737         33:934290717   | | | | | sqljcReceive entry
51738         33:934294324   | | | | | | clientCommCallback entry
51739         33:934304206   | | | | | | | CLI_utlGetInfo entry
51740         33:934306048   | | | | | | | CLI_utlGetInfo exit
51741         33:934309009   | | | | | | | sqlrxf2a entry
51742         33:934322190   | | | | | | | sqlrxf2a data [probe 4]
51743         33:934323299   | | | | | | | sqlrxf2a exit
51744         33:939817767   | | | | | | clientCommCallback exit
51745         33:939828871   | | | | | | sqlccrecv entry
51746         33:939830244   | | | | | | sqlccrecv data [probe 1]
51747         33:939832445   | | | | | | sqlccrecv data [probe 2]
51748         33:939833093   | | | | | | sqlccrecv data [probe 3]
51749         33:939833764   | | | | | | sqlccrecv data [probe 4]
51750         33:939834387   | | | | | | sqlccrecv data [probe 120]
51751         33:939835606   | | | | | | sqlccrecv data [probe 130]
51752         33:939837978   | | | | | | | sqlcctcprecv entry
51753         33:939838688   | | | | | | | sqlcctcprecv data [probe 1]
51754       33:939842723   | | | | | | | | tcprecv entry
51755      154:211882227   | | | | | | | | tcprecv data [probe 2]
51756        154:211896294   | | | | | | | | tcprecv exit
51757        154:211904245   | | | | | | | sqlcctcprecv exit
51758        154:211906988   | | | | | | sqlccrecv data [probe 5]
51759        154:211907763   | | | | | | sqlccrecv exit
...

诊断身份验证问题

当用户连接到数据库或附加到DB2实例时,认证由DB2外部的安全设施执行。 安全设施通常由DB2所在的操作系统提供。 根据配置,可以在服务器或客户端上进行身份验证。 DB2支持各种认证方法。 Further authentication information can be found in the DB2 Information Center, from the link in the Resources section .

A user which is on the same system as the database can connect using an implicit connect in which no user id and password are required or explicit connect in which a user id and password must be used. Connections to remote databases will usually require an explicit connect unless the server was configured for client authentication. When troubleshooting authentication issues, do not use an implicit connect because this bypasses any authentication mechanisms.

Troubleshooting authentication issues should be performed from outside the Java application via the DB2 CLP. Assuming that authentication has been configured to take place on the server. If an implicit connect executes quickly but an explicit connect exhibits a slow connect then there is likely a performance issue with authentication. Another indication of an authentication performance issue is that the initial time needed to establish a connect takes a long time, but there is no query response degradation for subsequent queries.

Listing 32. Explicit versus implicit authentication
$ db2 "connect to sample user db2inst1 using mypassword"

   Database Connection Information

 Database server        = DB2/AIX64 8.2.7
 SQL authorization ID   = DB2INST1
 Local database alias   = SAMPLE

$ db2 "connect to sample"

   Database Connection Information

 Database server        = DB2/AIX64 8.2.7
 SQL authorization ID   = DB2INST1
 Local database alias   = SAMPLE

On the AIX platform, DB2 uses the OS API getpwnam_r to get the user attributes. The AIX OS API getpwnam_r is a thread safe version of getpwnam. Following sample C program demonstrates the getpwnam_r and getpwnam calls.

Listing 33. Sample program calling O/S authentication APIs
#include <stdio.h>
#include <sys/types.h>
#include <pwd.h>
#include <errno.h>
#include <stdlib.h>
#include <unistd.h>
int main(int argc, char *argv[]) 
{ 
	int err = 0; 
	int rc = 0; 
	struct passwd *pResult = NULL; 
	struct passwd passwordData; 
	char *pBuffer = (char *)malloc(256); 
	if (argc != 2) 
	{ 
		printf("Usage: %s <userid> \n", argv[0]); 
		exit (1); 
	} 
	pResult = getpwnam(argv[1]); 
	if (pResult == NULL) 
	{ 
		err = errno; 
		printf("\n1: err: %d", err);
	} 
	else 
	{ 
		printf("getpwnam returned OK. \n"); 
	} 

	rc = getpwnam_r(argv[1], 
	&passwordData, 
	pBuffer, 
	256, 
	&pResult); 
	if ((rc != 0) || (pResult == NULL)) 
	{ 
		err = errno; 
		printf("\n2: err: %d, rc: %d\n", err, rc); 
	} 
	else 
	{ 
		printf("getpwnam_r returned OK. \n");
	} 
}

Save the code above as testgetpwnam.C and compile it generating the executable a.out. The command runs the program a.out that looks up user bianca and writes the amount of real, user, and system time to standard error.

Listing 34. Executing testgetpwnam program
$ xlc testgetpwnam.C

$ time ./a.out bianca

getpwnam returned OK.
getpwnam_r returned OK.

real 0m0.80s 
user 0m0.01s 
sys 0m0.00s

The output of ./a.out bianca shows user bianca is found by operating system calls getpwnam() and getpwnam_r() in addition to the time spent during execution. If execution time appears to be excessive, the AIX admin should be engaged to investigate the cause of delay that occurred in AIX

On the Windows platform, DB2 supports access tokens. Because access tokens are cached, this increases authentication performance. The access token support is enabled by using by setting the DB2 registry variable DB2_GRP_LOOKUP to TOKEN, TOKENLOCAL or TOKENDOMAIN. Access token support can be enabled with all authentication types except CLIENT authentication.

Listing 35. Windows authentication DB2 registry variables
db2set DB2_GRP_LOOKUP=,TOKEN
db2set DB2_GRP_LOOKUP=LOCAL,TOKENLOCAL
db2set DB2_GRP_LOOKUP=DOMAIN,TOKENDOMAIN

More information on DB2 access tokens can be found DB2 Information Center. Link from the

Related topics

section of this article.

Numerous applications making frequent short connections to DB2 server using SERVER_ENCRYPT authentication will experience performance degradation due to overhead associated with encryption/decryption. The obvious solution is to set authentication to SERVER, so that there is no need for decryption/encryption. However, if authentication cannot be set to SERVER due to security reasons, modify the applications to make less frequent long connections or utilize connection pooling

结论

Application performance problem determination is not trivial and can be further complicated by complexity of the environment. As the complexity of the environment increases, so is the effort expended to isolate the problem. This article demonstrated numerous tools to help isolate the components causing a performance bottleneck. We've looked at test cases of Java applications, Java routines, and networks for determining the causes of performance issues. We have also discussed diagnosing authentication performance problems on various platforms.

There is more than one way to isolate an application performance problem. With the use of the trace facilities and test cases demonstrated in this article, the application developer and database administrator should be able to formulate plans to diagnose various types of performance problems.

致谢

Special thanks to John Chun, Christine Law, Paolo Cirone, and Shakeb Shere for reviewing this article.


翻译自: https://www.ibm.com/developerworks/data/library/techarticle/dm-0708ma/index.html

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值