内容


权威支持

解读 WebSphere Application Server 跟踪文件

Comments

系列内容:

此内容是该系列 # 部分中的第 # 部分: 权威支持

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

此内容是该系列的一部分:权威支持

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

摘自 IBM WebSphere 开发者技术期刊

在每个专栏中,支持权威讨论了 IBM Technical Support 的可用于 WebSphere 产品的资源、工具和其他要素,以及一些可以进一步增强您的 IBM 支持体验的技术和新思想。

最新快报

按照当初的计划,我们会定期利用本专栏向您通报 WebSphere Support 领域的最新资源和理念,以下是您可能感兴趣的一些东西:

  1. 期盼已久的 IBM Support Assistant 的 fix pack 3.0.2 已经发布。此版本极大地提高了用于查找和下载新产品插件和新工具的内置更新管理器功能的速度。在有很多更新可用时,您不再需要等待 Update 面板刷新和从更新站点获取信息!通过进入 IBM Support Assistant 本身中的更新管理器,并选中 Available Plug-ins Updates 选项卡找到此新版本,就可以获得该版本。或者,可以通过 IBM Support Assistant 主网站下载完整的 IBM Support Assistant 新安装。

  2. IBM Guided Activity Assistant 的新版本 V3.0.4 也刚刚发布,其中包含多个非常便于使用的用户接口增强功能。IBM Guided Activity Assistant 继续提供用于帮助诊断更多问题类型的新内容主题。可以在 IBM Support Assistant Forum 找到更多信息。要获得 IBM Guided Activity Assistant 及 IBM Support Assistant 中的其他工具的所有更新,请直接通过 IBM Support Assistant 更新管理器下载。

  3. 最近对 WebSphere 家族产品的多篇技术说明特色文档进行了更新。这些特色文档总结了 IBM Technical Support 团队认为对每个产品的大部分客户最重要的信息和最新要闻。顺便提一句,最好能定期查看这些页面,以获得相关新信息。可以通过每个产品的 IBM Support 网站首页访问该产品的“特色文档”页面。例如,可访问 WebSphere Application Server 支持页面

  4. 在 Web 浏览器中为 WebSphere.org 创建书签,这是 WebSphere 用户全球社区的主页,包括博客、重要事件和新产品信息等内容。其中甚至包括专门处理支持问题的部分

接下来让我们继续今天的主话题……

跟踪简介

跟踪功能允许用户查看 WebSphere Application Server 代码级别的事件和方法执行顺序,以帮助确定出现问题的位置,从而进行诊断和解决。WebSphere Application Server 跟踪功能基于 java.util.logging 包。跟踪的细节级别由跟踪字符串控制,可以在其中指定希望跟踪单个类文件、整个 WebSphere Application Server 代码二进制或二者之间的任意级别。下面是几个示例:

表 1. 示例跟踪细节级别
跟踪字符串细节级别
com.ibm.ws.management.pidwaiter=all仅跟踪 PidWaiter 类
com.ibm.ws.webcontainer.*=all跟踪整个 WebContainer 组件
ChannelFrameworkService=all跟踪 ChannelFrameworkService 跟踪组
*=all跟踪所有组件

为了简化跟踪字符串规范,可使用跟踪组将常见 WebSphere Application Server 代码区域绑定到一起。例如,跟踪组“ChannelFrameworkService”同时跟踪通道框架组件代码和与通道框架交互的运行时代码。每个跟踪组件和组都基于产品版本定义,因此 WebSphere Application Server V5.xV6.x 的跟踪规范字符串彼此存在差异。

总的说来,WebSphere Application Server 支持团队建议使用 =all 作为跟踪级别。不过,还有其他一些选项,如 =Fine=Entry=Debug 等等。如果需要考虑性能开销,则最好设置更为具体的跟踪规范(细到单个类或组件)或级别较低的详细日志,从而确保尽可能减少对服务器的影响。有关每个环境和每种情况的最优跟踪设置指导信息,请咨询您的 WebSphere 支持专家或参考在线 MustGather 文档。可以在 WebSphere Application Server 信息中心中找到日志级别设置的所有可用选项及每个选项的描述。

务必知道,除了设置跟踪字符串外,一些组件还需要使用自定义属性或命令行参数来启用调试输出,如对于 ORB 组件要使用 com.ibm.CORBA.Debug=true,而对于 JSSE (SSL) 组件要使用 javax.net.debug=true。我们建议遵循信息中心或 MustGather 文档中的说明来正确地捕获信息。

V5.x 与 V6.x 的差异

WebSphere Application Server 的版本 5.x 与 6.x 的跟踪差异主要在于以下这些方面:

  • =enabled

    在 WebSphere Application Server V5.x 中,所有跟踪字符串都以 =enabled 结尾。例如:

    com.ibm.ws.webservices.*=all=enabled

    不过,在 V6.x 中取消了此参数,因此在 V6.x 中实现相同任务的跟踪规范将为:

    com.ibm.ws.webservices.*=all

    如果在 V6.x 中指定了包含 =enabled 的跟踪字符串,会自动将其更改为新格式。

  • 缺省跟踪规范

    在 WebSphere Application Server V5.x 中,缺省跟踪字符串为:*=all=disabled。因此,即使启用跟踪,也不会跟踪任何组件,将不会创建 trace.log。必须至少设置一个 =enabled,在 WebSphere Application Server V5.x 中才会实际发生跟踪。

    在 WebSphere Application Server V6.x 中,缺省跟踪字符串为 *=info。可以使用此设置控制 SystemOut.log 文件的日志记录级别。例如,如果仅希望将错误信息包含在日志中,则可以使用 *=fatal*=severe。不过,如果希望获得尽可能多的细节,则可以将此更改为 *=detail。从 *=fine*=all 的设置都会将跟踪输出到 trace.log 文件中。

如何启用跟踪

通过管理控制台选择 Troubleshooting => Logs and Trace => [ServerName] => Diagnostic Trace Service,可以启用 WebSphere Application Server 跟踪功能。(对于 V6.0 及更新版本的用户,Change Log Detail Levels 链接是实际设置跟踪字符串的位置。)

图 1. Diagnostic Trace Service
图 1. Diagnostic Trace Service
图 1. Diagnostic Trace Service
图 2. Change Log Detail Levels
图 2. Change Log Detail Levels
图 2. Change Log Detail Levels

Configuration 选项卡下指定跟踪设置时,将需要重新启动服务器,以使跟踪生效。不过,在 Runtime 选项卡下启用跟踪时,将立即生效(对于跟踪生产环境之类的环境非常有用,因为这种环境很难接受服务器重启)。不过,务必记住,除非选中了 Save runtime changes to configuration as well 框,否则服务器重新启动后将丢失运行时设置。另外,运行时跟踪仅报告当前系统信息;如果服务器已经存在问题,启用运行时跟踪将不会报告导致问题的原因,而仅会报告当前操作为何失败。因此,IBM Support 建议在 Configuration 选项卡下进行跟踪设置,以便能查看服务器重启情况,确定问题的根源。

Diagnostic Trace Service 面板(图 1)还允许指定除跟踪字符串之外的其他跟踪选项,如跟踪文件名、最大文件大小、历史备份文件数量以及跟踪格式。“Basic”跟踪格式是 WebSphere Application Server 支持团队的首选跟踪格式——同时也是缺省跟踪格式。Maximum File Size 和 Maximum Number of Historical Files 对于确保所捕获的跟踪信息不会被覆盖或丢失非常重要。在缺省情况下,文件大小设置为 20 MB,备份文件数量设置为一个。这意味着,当 trace.log 文件大小达到 20 MB 时,将创建新的 trace.log,并将之前的 trace.log 重命名为 trace_<date>.log,其中 <date> 是跟踪中的最后一个条目的日期和时间。不过,当新 trace.log 的大小再次达到 20 MB 时,会和前面一样创建新的跟踪文件,但之前的 trace_<date>.log 将被删除。因此,在出现复杂或费时的问题时,请务必确保 Number of Historical Files 和 Maximum File Size 足够大。Historical Files 的最大值为 20。WebSphere Application Server 支持团队喜欢将 Maximum File Size 保持在不大于 50 MB 的大小,因为文件大小太大将更难于加载和阅读。

WebSphere Application Server 信息中心提供了每个 Diagnostic Trace Service 设置及其描述的完整列表。

如果不能访问管理控制台,还可以通过 wsadmin 实用工具启用跟踪功能。可使用以下命令来在配置上启用跟踪功能(此示例将跟踪字符串设置为 com.ibm.ws.*=all=enabled):

set server [$AdminConfig getid /Cell:<mycell>/Node:<mynode>/Server:<myserver>/]
set tc [$AdminConfig list TraceService $server]
$AdminConfig modify $tc {{startupTraceSpecification com.ibm.ws.*=all=enabled}}
$AdminConfig save

同样,这仅在服务器重新启动后生效。要通过 wsadmin 启用运行时跟踪,请使用以下命令:

set ts [$AdminControl queryNames type=TraceService,node=<mynode>,process=<myserver>,*]
$AdminControl setAttribute $ts traceSpecification com.ibm.ws.*=all=enabled

信息中心提供了有关通过 wsadmin 工具启用跟踪功能的更多信息。

在不能访问管理控制台和 wsadmin 实用工具的情况下,则可以通过直接编辑相关服务器的 server.xml 文件来启用跟踪功能,但在没有其他选项可用的情况下才建议采用此方法,且仅在下次服务器启动之后才生效(没有运行时跟踪功能)。不正确地编辑文件可能导致服务器无法重新启动,因此强烈建议在编辑此文件前进行备份。还要记住,如果由于自动同步流程导致从部署管理器下推一个新副本,则可能最终会覆盖此 server.xml 文件。要编辑的具体 xml 标记如下:

<services xmi:type="traceservice:TraceService" xmi:id="TraceService_1149168481635" 
        enable="true" 
        startupTraceSpecification="*=info" 
        traceOutputType="SPECIFIED_FILE" 
        traceFormat="BASIC">
    <traceLog xmi:id="TraceLog_1149168481635" 
        fileName="${SERVER_LOG_ROOT}/trace.log" 
        rolloverSize="20" 
        maxNumberOfBackupFiles="1"/>

有关更多详细信息,请参见 how to setup a WebSphere Application Server trace

跟踪 Header

SystemOut.log 和 trace.log 文件顶部的 Header 包含关于生成日志的服务器的重要信息。

************ Start Display Current Environment ************
WebSphere Platform 6.0 [ND 6.0.2.15 cf150636.04]  running with process 
name carterfinleyNode02Cell\carterfinleyNode01\server1 and process id 
2744
Host Operating System is Windows XP, version 5.1
Java version = J2RE 1.4.2 IBM Windows 32 build cn142ifx-20061121 (ifix 
112270: SR6 + 111682 + 111872 + 110979) (JIT enabled: jitc), Java 
Compiler = jitc, Java VM name = Classic VM
was.install.root = C:\WebSphere60
user.install.root = C:\WebSphere60\profiles\AppSrv01
Java Home = C:\WebSphere60\java\jre
ws.ext.dirs = C:\WebSphere60/java/lib;C:\WebSphere60\profiles\AppSrv01/classes;C:\Web
Sphere60/classes;C:\WebSphere60/lib;C:\WebSphere60/installedChannels;C:
\WebSphere60/lib/ext;C:\WebSphere60/web/help;C:\WebSphere60/deploytool/
itp/plugins/com.ibm.etools.ejbdeploy/runtime
Classpath = C:\WebSphere60\profiles\AppSrv01/properties;C:\WebSphere60/properties;C
:\WebSphere60/lib/bootstrap.jar;C:\WebSphere60/lib/j2ee.jar;C:\WebSpher
e60/lib/lmproxy.jar;C:\WebSphere60/lib/urlprotocols.jar
Java Library path = C:\WebSphere60\java\bin;.;C:\WINNT\system32;C:\WINNT;C:\WebSphere60
\bin;C:\WebSphere60\java\bin;C:\WebSphere60\java\jre\bin;C:\WebSphere51\IBM
\WebSphere_MQ\Java\lib;C:\PROGRAM FILES\THINKPAD\UTILITIES;C:\WINNT\sys
tem32;C:\WINNT;C:\WINNT\System32\Wbem;(etc...)
Current trace specification = *=info:com.ibm.ws.security.*=all
************* End Display Current Environment *************

在每次服务器启动时也会生成此 Header。通过此 Header,可以看到具体的 WebSphere Application Server 级别和 Java™ 版本、计算单元名称、节点名称、服务器名称以及进程 ID。

此外,还可以看到类路径和 Java 库路径以及 WebSphere Application Server 变量 was.install.root 和 user.install.root。从跟踪角度而言,Header 中最重要的部分是最后一行,其中显示了当前所使用的跟踪字符串:

Current trace specification = *=info:com.ibm.ws.security.*=all

跟踪输出格式

所有可用 WebSphere Application Server 跟踪设置的实际跟踪输出格式都是一致的,信息中心对此进行了说明。其基本格式是:

[timestamp] <threadId> <className> <eventType> <methodName> <textmessage>

<methodName> 和 <textMessage> 参数都是可选的。以下是一个示例跟踪输出:

[2/5/07 13:13:49:457 EST] 0000000a ConfigFile    >  buildFileEntry() Entry
[2/5/07 13:13:49:457 EST] 0000000a ConfigFile    3   JAAS login configuration file: 
C:\WebSphere60\profiles\AppSrv01/properties/wsjaas.conf singleLogInFile: false
[2/5/07 13:13:49:497 EST] 0000000a ConfigFile    3   JAAS login configuration file: 
C:\WebSphere60\profiles\AppSrv01/properties/wsjaas.conf processed
[2/5/07 13:13:49:497 EST] 0000000a ConfigFile    <  buildFileEntry() Exit

通过上面的示例跟踪输出,可以看到:

  • 时间是东部时间 2007 年 2 月 5 日 13:13:49。
  • 跟踪输出显示了 ID 为 000000a 的单线程流程的情况。
  • 所执行的类名称是“ConfigFile”。

如果类名称大于 13 个字符,将仅显示前 13 个字符。

以下是每个跟踪条目行及其提供的信息的详细说明:

[2/5/07 13:13:49:457 EST] 0000000a ConfigFile > buildFileEntry() Entry

  • ConfigFile.buildFileEntry() 方法在此时开始执行。

[2/5/07 13:13:49:457 EST] 0000000a ConfigFile 3 JAAS login configuration file:
C:\WebSphere60\profiles\AppSrv01/properties/wsjaas.conf singleLogInFile: false

  • buildFileEntry() 代码中的调试语句。

[2/5/07 13:13:49:497 EST] 0000000a ConfigFile 3 JAAS login configuration file:
C:\WebSphere60\profiles\AppSrv01/properties/wsjaas.conf processed

  • buildFileEntry() 代码中的调试语句。

[2/5/07 13:13:49:497 EST] 0000000a ConfigFile < buildFileEntry() Exit

  • ConfigFile.buildFileEntry() 方法已完成执行并退出。

并非所有 WebSphere Application Server 代码都将输出方法进入点与退出点及调试消息。

投入实践

接下来,我们将看一些实际的场景,将在其中使用跟踪输出帮助调试问题。阅读 WebSphere Application Server 跟踪文件时的最佳实践是,跟踪所涉及的线程 ID,以了解事件流。(下载部分提供了用于拉取特定线程的脚本。)因此,您需要在 trace.log 文件中查找异常,然后再回到对应的线程 (00000033)。

示例 1

在此场景中,已经启用了 LDAP 服务器的全局安全性,无法登录到管理控制台。为了调试此问题,请遵循 Global Security problems for WebSphere Application Server(其中请求对复现的问题进行安全性跟踪)的 WebSphere Application Server MustGather 说明进行操作。

  1. 在问题服务器的 SystemOut.log 文件中找到问题期间发生的与您的情况相关的异常(例如,安全性或管理控制台)。对于本例,会发现以下异常:

    [2/6/07 11:25:43:802 EST] 00000033 LTPAServerObj E   SECJ0369E: 
    Authentication failed when using LTPA. The exception is [LDAP: error 
    code 49 - Invalid Credentials].
    [2/6/07 11:25:44:583 EST] 00000033 FormLoginExte E   SECJ0118E: 
    Authentication error during authentication for user joeuser@us.ibm.com

    步骤 1 中收集的信息非常重要,因为这提供了所涉及的线程 ID,即 00000033。这很有用,因为如果遇到具有不同线程 ID 的其他异常,就会知道这些异常很可能与此不相关,如以下片段中的情况:

    [2/6/07 11:26:11:972 EST] 00000038 wsMapDefaultI <  Exception 
    creating SAP tokens from WSCredential. Exit
    
    com.ibm.websphere.security.auth.WSLoginFailedException: Invalid 
    authentication data.
  2. 在 trace.log 文件中找到与步骤 1 中找到的错误的发生时间相近的具有相同线程 ID 的异常。

  3. 返回对应的线程查找关于为何生成此错误消息的更多信息。按照上面的说明操作,会发现此示例的 trace.log 中发生的情况如下:

    [2/6/07 11:25:43:151 EST] 00000033 ltpaLoginModu 3   Using uid and 
    password for authentication
    [2/6/07 11:25:43:151 EST] 00000033 ltpaLoginModu 3   Authenticating
    "myldap.raleigh.ibm.com:389/joeuser@us.ibm.com"
    [2/6/07 11:25:43:151 EST] 00000033 LTPAServerObj >  authenticate 
    Entry
    [2/6/07 11:25:43:151 EST] 00000033 UserRegistryI >  checkPassword 
    Entry
                                     joeuser@us.ibm.com
                                     ****
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI >  checkPassword 
    Entry
                                     joeuser@us.ibm.com
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Authenticating
                                     joeuser@us.ibm.com
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Searching for 
    users
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI >  getUsers Entry
                                     joeuser@us.ibm.com
                                     2
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI >  search Entry
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   DN: o=ibm.com
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Search scope: 2
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Filter: 
    (&(mail=joeuser@us.ibm.com)(objectclass=person))
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Time limit: 3
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   Attr[0]: 1.1
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI >  getDirContext 
    Entry
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI <  getDirContext 
    Exit
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI <  getDirContext 
    Exit
    [2/6/07 11:25:43:151 EST] 00000033 LdapRegistryI 3   
    enterJNDI:WebContainer : 1
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI 3   
    exitJNDI:WebContainer : 1
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI 3   Time elapsed: 80
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI <  search Exit
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI 3   Number of users 
    returned = 1
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI <  getUsers Exit
                                     joeuser@us.ibm.com
                                     2
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI 3   Found user
                                     uid=joeuser,c=person,o=ibm.com
    [2/6/07 11:25:43:231 EST] 00000033 LdapRegistryI 3   
    enterJNDI:WebContainer : 1
    [2/6/07 11:25:43:562 EST] 00000033 LdapRegistryI 3   
    exitJNDI:WebContainer : 1
    
    [2/6/07 11:25:43:662 EST] 00000033 LdapRegistryI <  checkPassword Exit
                                     javax.naming.AuthenticationException: 
    [LDAP: error code 49 - Invalid Credentials]
    	at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3005)
    	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2951)
    	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2752)
    	at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2666)
    	at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:307)
    	at 
    com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:190)
    	at 
    com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:208)
    	at 
    com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java
    :151)
    	at 
    com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:
    81)
    	at 
    javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:675)
    	at 
    javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:257)
    	at javax.naming.InitialContext.init(InitialContext.java:233)
    	at 
    javax.naming.InitialContext.<init>(InitialContext.java:209)
    	at 
    javax.naming.directory.InitialDirContext.<init>(InitialDirContext
    .java:94)
    	at 
    com.ibm.ws.security.registry.ldap.LdapRegistryImpl.authenticate(LdapReg
    istryImpl.java:370)
    	at 
    com.ibm.ws.security.registry.ldap.LdapRegistryImpl.checkPassword(LdapReg
    istryImpl.java:312)
    	at 
    com.ibm.ws.security.registry.UserRegistryImpl.checkPassword(UserRegistr
    yImpl.java:296)
    	at 
    com.ibm.ws.security.ltpa.LTPAServerObject.authenticate(LTPAServerObject
    .java:573)
    	at 
    com.ibm.ws.security.server.lm.ltpaLoginModule.login(ltpaLoginModule.jav
    a:437)
    ...
    [2/6/07 11:25:43:802 EST] 00000033 LTPAServerObj E   SECJ0369E: 
    Authentication failed when using LTPA. The exception is [LDAP: error 
    code 49 - Invalid Credentials].

从上面的跟踪输出中可以看到,在 LdapRegistryI* 类的 checkPassword 方法退出时发生了异常。继续到 00000033 线程,可以看到对用户 ID joeuser@us.ibm.com(执行登录尝试的 ID)调用了 checkPassword 方法。如果进一步回溯线程,会发现所使用的用户注册中心是 LDAP 注册中心 myldap.raleigh.ibm.com:389。这清楚地表明登录时输入的密码与 LDAP 注册中心中的用户 ID 对应密码不匹配。

示例 2

事务超时是另一个经常出现的常见问题。当启用了包括 Transaction=all 跟踪字符串的跟踪时,就可以确定事务超时的原因了。由于到后端系统(如数据库)的连接通常在事务中获取,因此这时也启用对连接管理器的跟踪将很有用。组合后的跟踪字符串将为 *=info:Transaction=all:WAS.j2c=all

分析事务跟踪信息时,通常有必要分析多个线程,而这将增加跟踪分析的复杂性。拥有大量的历史跟踪数据也非常重要。这是因为在缺省情况下事务将会在处于活动状态 120 秒后超时,这意味着您至少需要在事务超时前 120 秒钟的跟踪数据。

  1. 在应用服务器 SystemOut.log 文件中找到事务超时的时间戳。事务超时始终由 WTRN0006W 消息进行指示。例如:

    [1/24/07 14:59:52:662 EST] 0000000f TimeoutManage I   WTRN0006W: Transaction
    0000011056531F8D000000050001C7E40B304AAB611AB4FC574CE136F63A9E07BE
    78A01B0000011056531F8D000000050001C7E40B304AAB611AB4FC574CE136F63A
    9E07BE78A01B00000001 has timed out after 120 seconds.
  2. 现在已经知道了事务超时出现的时间,接下来可以在跟踪信息中寻找相同的条目。您将需要向下寻找多行信息中的线程 ID 0000000f,以找到事务 ID。

    [1/24/07 14:59:52:662 EST] 0000000f TimeoutManage I   WTRN0006W: Transaction 
    0000011056531F8D000000050001C7E40B304AAB611AB4FC574CE136F63A9E07BE
    78A01B0000011056531F8D000000050001C7E40B304AAB611AB4FC574CE136F63A
    9E07BE78A01B00000001 has timed out after 120 seconds.
    [1/24/07 14:59:52:680 EST] 0000000f TransactionIm >  timeoutTransaction Entry
    		true
    [1/24/07 14:59:52:680 EST] 0000000f TransactionIm 3   Tx timed out
    		Started: 1169679392659, Commit requested: 0, Prepare phase begin: 
    0, Commit phase begin: 0, Current time: 1169679592680
    [1/24/07 14:59:52:680 EST] 0000000f TransactionIm 1   (SPI) Transaction TIMEOUT 
    occurred for TX: 116708

    此处跟踪信息最后一行表明所超时的事务的 ID 为 116708。

    正如前面提到的,您将需要分析跟踪信息中的多个线程。这是因为 WebSphere Application Server 使用专用线程来监视事务运行所用的时间。实际事务活动在不同的线程上进行,此线程通常为 Web 容器线程(对于 Servlet)或 ORB 线程(对于 EJB 应用程序)。

  3. 现在必须找到事务活动在其上进行的线程。可以通过使用事务 ID 完成此任务。搜索跟踪数据,以找到以下字符串的第一个匹配项:TX: 116708。将发现与以下类似的跟踪条目:

    [1/24/07 14:57:52:659 EST] 0000015d TransactionIm 1   (SPI) Transaction BEGIN 
    occurred for TX: 116708

    毫无意外,我们看到了事务准确地在超时前 120 秒钟开始。从这个跟踪条目中可以看到,事务活动出现在线程 0000015d 上。现在可以分析线程 0000015d 来确定什么原因导致了事务超时。(本文所包括的 pullThread 脚本可以帮助将此特定线程的跟踪条目分离出来。您的文本编辑器可能具有搜索功能,可显示包含指定字符串的所有行。如果是这样,可以使用此功能查找包含 0000015d 的所有行。如果不行,仍然能以手动方式查找线程。)

  4. 查看跟踪信息中有关事务活动在其上发生的线程的行。在此示例中,线程 ID 为 0000015d。实际文本没有时间戳重要。您需要检查连续跟踪条目时间戳中明显的差异。通常,每个跟踪条目将仅比前一跟踪条目晚数毫秒。应该寻找时间戳差异大于五秒的连续跟踪条目。此类时间戳差异称为“差距”。

    如果未看到任何重大差异,则可以确定事务中没有操作的执行速度过慢。这可能意味着事务中存在大量操作,为了考虑到这一点,将需要将应用服务器上的缺省总事务生命时间超时增大为高于缺省 120 秒的值。

    另一方面,如果发现差距,这将有助于帮助确定导致事务超时的原因。例如,可能会发现以下两个跟踪条目间存在差距:

    [1/24/07 14:57:52:672 EST] 0000015d WSJdbcPrepare >  executeQuery Entry
    [1/24/07 14:58:06:687 EST] 0000015d WSJdbcPrepare <  executeQuery Exit

    这表明进入 executeQuery 方法的条目与从 executeQuery 方法退出的条目之间存在 14 秒的差距。多个这样的差距可能会导致事务的执行时间超过 120 秒,从而导致事务超时。现在已经找到了差距所在,接下来可以尝试修复问题了。在此示例中,我们知道 executeQuery 方法中存在差距,即数据库查询返回的时间很长。您将咨询数据库管理员,以调查为何查询执行时间这么长。您可能会在较为不明显的方法或看起来完全不相关的跟踪条目中发现差距。在这种情况下,将可能需要联系 IBM Support 来解决问题。

    您还可能会发现,在特定跟踪条目之后,该线程上没有任何活动了。这可能意味着线程由于等待已挂起或停滞了。此时,可以生成 javacores 来了解挂起线程的堆栈跟踪信息。例如与以下类似的跟踪条目:

    [1/24/07 14:58:32:725 EST] 0000015d FreePool      >  createOrWaitForConnection 
    Entry

    此跟踪条目表明线程在等待 WebSphere Application Server 连接池中的空闲连接。在 javacore 中,将在此线程的堆栈跟踪信息顶部看到 com.ibm.ejs.j2c.poolmanager.FreePool.createOrWaitForConnection。增大最大连接池大小可以帮助缓解此问题。跟踪信息中的条目和 javacore 中的线程转储可能会(也可能无法)提供确定问题原因的足够信息。如果没有足够的信息,或者无法解释跟踪条目的含义,则应该联系 IBM Support。

用于分析跟踪信息来确定事务超时的原因的方法还可以用于解决其他类型的问题。如果您遇到了任何性能低下的问题,可以在跟踪条目中寻找各个线程中存在的差距,从而确定性能低下的情况出现在哪个位置。

用于读取跟踪信息的工具

Trace Analyzer for WebSphere Application Server 允许您利用更为用户友好的 GUI 界面查看基于文本的复杂跟踪文件。跟踪文件的内容划分为行和列,这更便于阅读。此工具包含很多有用的功能,如查找对应的进入点和退出点,跟踪单个线程,甚至还能生成调用堆栈。

图 3. Trace Analyzer for WebSphere Application Server
图 3. Trace Analyzer for WebSphere Application Server
图 3. Trace Analyzer for WebSphere Application Server

调试跟踪时,通常采用提取所感兴趣的线程的方法会更为方便,因为这样只需要查看与相关线程关联的条目即可。可以通过类似于 pullThread.sh 脚本(本文已提供,用于非 Windows® 系统)的脚本来完成此工作。缺省情况下,此脚本会将输出打印到提示处,不过您可以方便地通过管道命令使用此输出创建另一个日志文件。

用于使用此脚本的命令如下:

./pullThread.sh <threadID> <tracefile>

带实参值的命令如下所示:

./pullThread.sh 00000033 trace.log > NewTrace.log

结束语

跟踪功能是 WebSphere Application Server 和其他 WebSphere 产品中提供的众多内置故障诊断工具之一。欢迎您定期访问本专栏,以了解我们提供的关于 IBM Support 相关的工具和资源的最新实用信息。

致谢

作者感谢 Dave Tiler 提供的事务跟踪示例和 James Kochuba 对本文的反馈与建议。


下载资源


相关主题


评论

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

static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=10
Zone=WebSphere
ArticleID=225945
ArticleTitle=权威支持: 解读 WebSphere Application Server 跟踪文件
publish-date=05242007