示例 2
事务超时是另一个经常出现的常见问题。当启用了包括 Transaction=all 跟踪字符串的跟踪时，就可以确定事务超时的原因了。由于到后端系统（如数据库）的连接通常在事务中获取，因此这时也启用对连接管理器的跟踪将很有用。组合后的跟踪字符串将为 *=info:Transaction=all:WAS.j2c=all。
分析事务跟踪信息时，通常有必要分析多个线程，而这将增加跟踪分析的复杂性。拥有大量的历史跟踪数据也非常重要。这是因为在缺省情况下事务将会在处于活动状态 120 秒后超时，这意味着您至少需要在事务超时前 120 秒钟的跟踪数据。
在应用服务器 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.
现在已经知道了事务超时出现的时间，接下来可以在跟踪信息中寻找相同的条目。您将需要向下寻找多行信息中的线程 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 应用程序）。
现在必须找到事务活动在其上进行的线程。可以通过使用事务 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 的所有行。如果不行，仍然能以手动方式查找线程。）
查看跟踪信息中有关事务活动在其上发生的线程的行。在此示例中，线程 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 
调试跟踪时，通常采用提取所感兴趣的线程的方法会更为方便，因为这样只需要查看与相关线程关联的条目即可。可以通过类似于 pullThread.sh 脚本（本文已提供，用于非 Windows® 系统）的脚本来完成此工作。缺省情况下，此脚本会将输出打印到提示处，不过您可以方便地通过管道命令使用此输出创建另一个日志文件。
用于使用此脚本的命令如下：
./pullThread.sh <threadID> <tracefile>
带实参值的命令如下所示：
./pullThread.sh 00000033 trace.log > NewTrace.log
结束语
跟踪功能是 WebSphere Application Server 和其他 WebSphere 产品中提供的众多内置故障诊断工具之一。欢迎您定期访问本专栏，以了解我们提供的关于 IBM Support 相关的工具和资源的最新实用信息。
