IBM WebSphere Developer Technical Journal（US）より。

各コラムのサポート情報では、WebSphere製品で使用可能な IBMテクニカル・サポートのリソース、ツール、およびその他の要素について説明します。また、IBMサポートの技術を更に強化できるテクニックや新しい概念についても説明します。

新着情報

このスペースを定期的に使用してWebSphereサポート分野の新しいリソースや概念を読者にお伝えしていこうと考えていますが、今回は注目すべき新しい記事をいくつかご紹介します。

1. IBM Support Assistantに待望のフィックス・パック 3.0.2がリリースされました。このリリースにより、組み込みの更新マネージャー機能を使用して新しい製品プラグインやツールを検索/ダウンロードする速度が劇的に向上します。多数の更新が提供されていても、「更新」パネルで情報を最新表示したり、更新サイトから情報を取り出したりするのに時間がかかりません。この新しいリリースを入手するには、IBM Support Assistant自体の更新マネージャーを使用して、「使用可能なプラグインの更新（Available Plug-ins Updates）」タブでそれがないかどうかを調べます。または、メインのIBM Support Assistant Webサイト（US）から、IBM Support Assistantの完全な新規インストールをダウンロードすることもできます。

2. 新しいバージョンのIBM Guided Activity Assistant（バージョン 3.0.4）もリリースされました。このバージョンには、ユーザー・インターフェースの使いやすさに関する重要な拡張機能がいくつか組み込まれています。IBM Guided Activity Assistant は、さまざまな問題を診断するのに役立つ新しいコンテンツ・トピックを引き続き提供します。詳しくは、IBM Support Assistant Forum（US）を参照してください。IBM Guided Activity Assistantおよびその他のツールの更新をIBM Support Assistantですべて入手するには、IBM Support Assistantの更新マネージャーを使用します。

3. WebSphereファミリー製品の技術情報の「特集記事（Featured Documents）」のいくつかが、最近更新されました。これらの特別な資料には、各製品のユーザーの大部分に非常に有益であるとIBMテクニカル・サポート・チームが考える情報や最近のニュースがまとめられています。念のため、これらのページに新しい情報がないかどうかを、定期的に調べることをお勧めします。各製品の「特集記事（Featured Documents）」ページは、その製品のIBM Support Webサイトの表紙からアクセスできます。例えば、WebSphere Application Serverのサポート・ページ（US）にアクセスしてください。

4. WebブラウザーでWebSphere.org（US）のブックマークを作成します。WebSphere.orgは、WebSphereユーザーのグローバル・コミュニティーのホーム・ページであり、ブログ、イベント、および新製品の情報が含まれています。また、サポートの問題を専門に扱うセクション（US）も含まれています。

この辺で、本題に戻りましょう

上に戻る

トレースの概要

トレースを使用すると、実行中のイベントおよびメソッドのシーケンスをWebSphere Application Serverコード・レベルで確認できます。そのため、問題の発生箇所を容易に特定して、問題を診断および解決することが可能です。WebSphere Application Serverのトレースは、java.util.loggingパッケージに基づいています。トレースの詳細レベルは、トレース・ストリングで制御されます。トレース・ストリングでは、単一のクラス・ファイルをトレースするのか、WebSphere Application Serverコード・ライブラリー全体をトレースするのか、それともそれらの間の任意のレベルでトレースするのかを指定できます。以下に例をいくつか示します。

表1. トレース詳細レベルのサンプル

トレース・ストリングの指定を簡素化するために、トレース・グループは、共通のWebSphere Application Serverコード領域を一緒にバンドルします。例えば、トレース・グループ「ChannelFrameworkService」は、チャネル・フレームワーク・コンポーネント・コードと、チャネル・フレームワークと対話するランタイム・コードの両方をトレースします。それぞれのトレース・コンポーネントとグループは、製品のバージョンに基づいて定義されます。そのため、WebSphere Application Serverバージョン5.x（US）とバージョン6.x（US）では、トレース指定ストリングが異なります。

通常、WebSphere Application Serverサポート・チームは、トレース・レベルとして=allを使用することを推奨しています。ただし、=Fine、=Entry、=Debugなど、他のオプションも用意されています。パフォーマンスのオーバーヘッドが問題になる場合は、より具体的なトレース指定（単一のクラスまたはコンポーネント）を設定するか、ログ・レベルの詳細度を低く設定して、サーバーへの影響を最小限に抑えるのがよい方法です。それぞれの環境および状況のタイプに最適なトレース設定については、WebSphereサポートの専門家に問い合わせるか、オンラインMustGather文書（US）を参照してください。それぞれの使用可能なすべてのオプションと説明は、WebSphere Application Serverインフォメーション・センター（US）のログ・レベル設定に関する文書に記載されています。

重要なことですが、一部のコンポーネントでは、デバッグ出力を得るために、トレース・ストリングの設定だけではなく、カスタム・プロパティーまたはコマンド行引数も必要です（例えば、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 =enabledを含むトレース・ストリングをV6.xで指定した場合、そのトレース・ストリングは、自動的に新しい形式に変更されます。

• デフォルトのトレース指定

  WebSphere Application Server V5.xの場合、デフォルトのトレース・ストリングは*=all=disabledです。したがって、たとえトレースが有効であっても、コンポーネントはトレースされず、trace.logは作成されません。WebSphere Application Server V5.xで実際にトレースを行うには、=enabledを1つ以上設定する必要があります。

  WebSphere Application Server V6.xの場合、デフォルトのトレース・ストリングは*=infoです。SystemOut.log ファイルのロギング・レベルは、この設定で制御できます。例えば、エラーのみをログに記録する場合は*=fatalまたは*=severeを使用しますが、できるだけ詳細な情報が必要な場合は、これを*=detailに変更します。*=fineから*=allを設定すると、トレース出力がtrace.logファイルに記録されます。

上に戻る

トレースを有効にする方法

WebSphere Application Serverのトレースを有効にするには、管理コンソールから、「トラブルシューティング」=>「ログおよびトレース」=> [ServerName] =>「診断トレース・サービス」を選択します。（v6.0およびそれ以降のバージョンを使用する場合、トレース・ストリングを実際に設定する場所は、「ログ詳細レベルの変更」リンクです。）

「構成」タブの下でトレース設定を指定した場合、トレースを有効にするには、サーバーを再始動する必要があります。一方、「ランタイム」タブの下でトレース設定を指定した場合は、それがただちに有効になります（これは、サーバーの再始動を許容できない実稼働環境などのトレース環境で非常に便利です）。ただし、これは重要なことですが、「ランタイム変更も構成に保管する」ボックスがチェックされていない場合、ランタイムの設定はサーバーを再始動すると失われます。また、ランタイム・トレースでは、現在のシステム情報のみが報告されます。サーバーですでに問題が起こってしまった後では、ランタイム・トレースを有効にしても、問題の原因は記録されず、現在のアクションが失敗した理由のみが報告されます。したがって、IBMサポートでは、サーバーの始動を検討し、問題の根本原因を特定できるようにするために、トレース設定を「構成」タブの下で行うことを推奨しています。

「診断トレース・サービス」パネル（図1）では、トレース・ストリングに加えて、その他のトレース・オプションを指定することもできます（トレース・ファイル名、最大ファイル・サイズ、ヒストリー・バックアップ・ファイルの数、トレース形式など）。「基本」トレース形式は、WebSphere Application Serverサポート・チームが優先的に使用するトレース形式であり、デフォルトのトレース形式でもあります。「最大ファイル・サイズ」と「ヒストリー・ファイルの最大数」は、収集するトレース情報が折り返されたり、失われたりしないようにするために重要です。デフォルトでは、ファイル・サイズとして20MB、バックアップ・ファイルの数として1が設定されています。つまり、trace.logファイルのサイズが20MBに達すると、新しいtrace.logが作成され、直前のtrace.logはtrace_<date>.logという名前に変更されます（<date>は、トレースの最後のエントリーの日時です）。ただし、新しいtrace.logのサイズが再び20MBに達すると、前回と同様に新しいトレース・ファイルが生成されますが、それまであったtrace_<date>.logは削除されます。したがって、複雑な問題や時間を要する問題を再現するときは、「ヒストリー・ファイルの最大数」と「最大ファイル・サイズ」を十分に大きくしておくことが重要です。ヒストリー・ファイルの数として設定できる最大値は20です。WebSphere Application Serverサポート・チームは、最大ファイル・サイズを常に50MB以下に設定しています。なぜなら、ファイル・サイズが大きくなりすぎると、トレースのロードと読み取りが大変になるからです。

「診断トレース・サービス」の各設定とその説明について詳しくは、WebSphere Application Serverインフォメーション・センター（US）を参照してください。

管理コンソールを利用できない場合は、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ツールでトレースを有効にする（US）』手順がより詳しく説明されています。

管理コンソールと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"/>

詳しくは、『WebSphere Application Serverトレースの設定方法（US）』の技術情報を参照してください。

トレース・ヘッダー

SystemOut.logファイルおよびtrace.logファイルの上部にあるヘッダーには、ログを生成したサーバーに関する有益な情報が含まれています。

************ 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 *************

このヘッダーは、サーバーを始動するたびにも生成されます。このヘッダーからは、プロセスIDとともに、厳密なWebSphere Application ServerのレベルとJava™のバージョン、セル名、ノード名、サーバー名を知ることができます。

さらに、クラスパスとJava libパスの内容をはじめ、WebSphere Application Serverの変数（was.install.root および user.install.root）も知ることができます。トレースの観点から言えば、ヘッダーの最も有益な部分は、現在使用しているトレース・ストリングを示す最後の行です（下記参照）。

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

上に戻る

トレースの出力形式

実際のトレース出力の形式は、使用可能なすべてのWebSphere Application Serverトレース・ストリングで一貫しています。この形式は、インフォメーション・センター（US）で文書化されています。基本的な形式を以下に示します。

[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 サーバーに対してグローバル・セキュリティーを有効にしており、管理コンソールにログインできません。この問題をデバッグするには、WebSphere Application Serverのグローバル・セキュリティー（US）の問題に関する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ファイルで、同じスレッドIDを持つ例外のうち、ステップ1で見つかったエラーとほぼ同時刻に発生したものを探します。

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スレッドを上に見ていくと、checkPasswordメソッドは、ログインを試行したユーザーID、joeuser@us.ibm.comで呼び出されていることがわかります。スレッドをさらにさかのぼると、使用されているユーザー・レジストリーは、LDAPレジストリーmyldap.raleigh.ibm.com:389であることがわかります。このことから、ログイン時に入力したパスワードが、このユーザーIDのLDAPレジストリーのパスワードに一致していないということが明らかになります。

例 #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コンテナー・スレッド、EJBアプリケーションの場合はORBスレッド）。

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です。実際のテキストは、タイムスタンプほど重要ではありません。連続するトレース・エントリーについて、それらのタイムスタンプに顕著な差がないかどうかを調べる必要があります。通常、各トレース・エントリーは、その直前にあるトレース・エントリーのわずか数ミリ秒後（またはそれより短い時間の後）に作成されます。連続するトレース・エントリー間で、タイムスタンプの差が約5秒を超えるものを探す必要があります。そのようなタイムスタンプの差は、「ギャップ」と呼ばれます。

   著しいギャップがない場合は、速度が遅すぎる操作がトランザクション内に存在しないと結論付けることができます。これは、トランザクション内に多数の操作が存在していることを意味しますが、これに対応するには、アプリケーション・サーバー上のデフォルトの合計トランザクション存続時間タイムアウトを、デフォルトの120秒より大きな値にする必要があります。

   一方、ギャップがあった場合、そのギャップは、トランザクションがタイムアウトになった原因を特定するのに役立ちます。例えば、以下の2つのトレース・エントリーの間には、ギャップがあります。

   
   
   

   [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サポートに連絡して、問題をトラブルシューティングする必要があります。

   また、特定のトレース・エントリーの後に、スレッドのアクティビティーが存在しなくなる場合もあります。これは、スレッドがハングしているか、または何かを待機中にスレッドが動かなくなっていることを意味する場合があります。その場合は、javacoreを生成して、ハングしたスレッドのスタック・トレースを確認するのが有用です。例として、以下のようなトレース・エントリーを示します。

   
   
   

   [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サポートに連絡してください。

トレースを分析してトランザクション・タイムアウトの原因を特定するために使用する方法は、他のタイプの問題にも使用できます。パフォーマンスが低下する問題が発生した場合は、個々のスレッドのトレース・エントリーのギャップを探して、どこでパフォーマンスが低下しているのかを確認できます。

上に戻る

トレースを読み取るツール

WebSphere Application Serverのトレース・アナライザー（US）では、複雑なテキスト・ベースのトレース・ファイルを、より使いやすいGUIインターフェースで表示できます。トレースの内容は、行と列に分割されているため、容易にトレースを読み取ることができます。このツールには、便利な機能が多数組み込まれており、例えば、対応するエントリーと出口点を検索したり、単一のスレッドを追跡したり、さらには呼び出しスタックを生成することも可能です。

通常、トレースをデバッグするときは、関係のあるスレッドを比較的簡単に抜き取ることができます。そうすれば、それぞれのスレッドの関連するトレース・エントリーを参照するだけでよくなります。これは、この記事に記載している pullThread.shスクリプトと同等のスクリプトを非Windows®システム上で使用することにより行うことができます。デフォルトでは、このスクリプトの出力はプロンプトに送られますが、パイプを通じて別のログ・ファイルを作成することも容易に行えます。

このスクリプトを使用するコマンドを以下に示します。

./pullThread.sh <threadID> <tracefile>

実際のパラメーター値を指定したコマンドは、以下のようになります。

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

上に戻る

まとめ

トレース機能は、WebSphere Application ServerなどのWebSphere製品に組み込まれている多数のトラブルシューティング・ツールの一つです。私たちは、IBMサポート関連のツールやリソースに関する最新情報および実践的な情報をこれからも提供していきますので、このコラムをときどき確認してください。

上に戻る

謝辞

Dave Tiler氏には、トランザクション・トレースの例を提供していただきました。James Kochuba氏には、ご意見やご提案をいただきました。この両氏に感謝いたします。

上に戻る

ダウンロード

ダウンロード形式について

参考文献

学ぶために

• developerWorks Japan: WebSphere: WebSphereの日本の技術情報サイトです
  
  
• developerWorks: WebSphere(US) : WebSphereの英語の技術情報サイトです
  
  
• The Support Authority:If you need help with WebSphere products, there are many ways to get it（US）
  
  
• IBM Software Support Web サイト（US）
  
  
• IBM Software Support Handbook（US）
  
  
• 製品資料（US）
  
  
• IBM developerWorks（US）
  
  
• IBM Redbooks（US）
  
  

製品や技術を入手するために

• IBM Support Assistant（US）
  
  

議論するために

• フォーラムおよびニュース・グループ（US）
  
  

著者について

David Hareは、2003年にIBMに加わりました。ポータルおよびEclipseのテスト・チームとともに作業した後、現在は、WebSphere Application Server Level 2 SupportチームのStaff Software Engineerとして働いています。David Hareは、セキュリティー、SSL、システム管理、wsadmin、および管理コンソールの問題を顧客が解決できるように支援する管理チームを率いています。
dwhare@us.ibm.com

Daniel Julin は、複合オンライン・システムの開発およびトラブルシューティングに 20 年の経験を積んでいます。WebSphere Serviceability Team の技術面でのリーダーとして、現在は主に WebSphere Application Server での問題判別を支援し、IBM サポートの効果を最大限に生かす一連のツールおよび技術を定義、実装する上でのチームの活動を手伝っています。また、さまざまな局面で重要なカスタマー・サポートに直接関わることもあります。

この記事を評価する

コメント

上に戻る

目次

• 新着情報
• トレースの概要
• V5.xとV6.xの違い
• トレースを有効にする方法
• トレースの出力形式
• トレースの実行
• トレースを読み取るツール
• まとめ
• 謝辞
• ダウンロード
• 参考文献
• 著者について
• コメント