Comments
Description
Transcript
問題判別 1 WASV7.0によるWebシステム基盤設計Workshop
WASV7.0によるWebシステム基盤設計Workshop
問題判別
1
当セッションの目的
問題判別を行うに当たっての心得について確認する
基本手順、確認すべきサイト、情報収集方法
問題判別のポイントについて理解する
各コンポーネントのログ・トレース
¾
JVM問題判別方法
¾
Edge Component、IHS、プラグイン、WASのそれぞれのログと、トレース取得方
法
verbose:gc、JavaDump、HeapDumpのそれぞれの解析ツールとその使用例
症状別問題判別方法
¾
ブラウザへ応答が返ってこないときの問題判別の一例、ハング/ループ、スロー
ダウン、OutOfMemory、クラッシュなど、代表的な症状における問題判別方法
2
2
Agenda
１. 問題判別の心得
１－１ 問題判別の基本
１－２ 情報収集・問題判別ツール
２.問題判別
２－１ ログ、トレース
２－２ JVM問題判別
２－３ 症状別問題判別
まとめ・参考文献
3
3
１.問題判別の心得
１－１ 問題判別の基本
１－２ 情報収集・問題判別ツール
4
4
問題判別の基本手順
問題発生
• プロセスの生存確認
• 各コンポーネントの応答調査
• ログメッセージの確認
等
問題の種類 / 発生箇所の特定
対応策
・パッチの適用
・設定の変更
・アプリの修正
…
問題原因の究明
採集資料（ログやトレース）の分析
既知の問題
再現手順の調査
さらなる資料の採集・分析
既知情報の
収集
情報の保存
質問・採集した資料の送付
サポートセンターに連絡
5
上記は、WebSphere製品に関わらず、一般的なOS/ソフトウェア製品の問題判別の基本手順になります。
問題判別とは、発生した問題の原因を特定し、その問題を解決するための対応策を実施して、問題が解
決したことをテストで確認するための作業です。
問題が発生したら、その問題の種類や発生箇所の分析を行います。そして、取得したログやトレースを使
用して、その問題が起こっている原因を究明します。その原因に応じて、パッチの適用や設定の変更、アプ
リケーションの修正などといった対応をします。原因が既知の問題である場合には既知情報を収集し、その
問題に対して適切な対応をします。
次に、その問題の再現性について調査します。再現性がある場合はその再現手順について調査します。
そして、さらに公開されている資料や既知情報をもとに問題の分析を行います。ここで調査した情報を、今
後同じような問題が起こったときのために残しておくことも大切になります。
最終的に問題への対応方法が分からず、解決されない場合は、サポートセンターに連絡し解析を依頼し
ます。その際、質問内容と一緒にログやトレースなどの採集した資料も送付します。
5
問題が起こる前に
障害情報や修正プログラム情報の収集
WASサポート・サイトから最新リリースをチェック
¾
最新リリースの適用を推奨
障害情報の確認
問題の発生を想定した設計・構成
WASクラッシュ時にヒープダンプを出力させる
ログやダンプなど、ファイル出力先のサイズに余裕を持たせる
計画的なFixpackを適用
機能テスト、パフォーマンステストの実施
プロジェクト体制
障害発生時の役割分担、体制などの明確化
6
問題が発生する前に、それに備えておくべきこととしては、まず障害情報や修正プログラム情報の収集が
挙げられます。これらの情報は、WASのサポート・サイトから得ることが出来ます。WASサポート・サイトは、最
新リリースの情報や障害に関する情報が随時更新されており、これらを事前に調べておくことが望ましいで
す。
また、WASの導入にあたっては最新リリースの適用が推奨されます。更に本番システムを構築するにあた
り、機能テスト、パフォーマンステストを事前に行っておくことや障害発生時の役割分担などプロジェクト体制
を明確化することも重要です。
お客様要件や運用方針などにもよりますが、システムがサービス・インしてからも極力最新リリースにするこ
とが望ましく、適用を見送る場合でも、その検討は随時行うことをおすすめします。
6
はじめに、確認すべきサイト
Information Center - (製品マニュアル)
WASサポート・サイト
過去のQA情報などが検索できる
http://www-1.ibm.com/support/jp/search/index.html
Defect・List
日本語の技術情報や連載記事、Workshop資料を入手可能
http://www.ibm.com/developerworks/jp/websphere/index.html
テクニカル・サポート検索
Technotesや既知の障害情報を検索可能
http://www-306.ibm.com/software/webservers/appserv/was/support/
developerWorks
http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/index.jsp
RefreshPack・FixPackによる機能追加・修正内容の一覧表示
http://www01.ibm.com/support/docview.wss?rs=180&context=SSEQTP&q1=Fix+List&uid=swg27
014463&loc=en_US&cs=utf-8&lang=en
iFix・List（Edge)
iFixによる修正内容を日本語にて一覧表示
http://www06.ibm.com/jp/software/websphere/download/ifix/was/edge/learnmore.html
7
上記は、問題判別の際に、”はじめに確認すべきサイト”として纏めさせて頂きました。WASサポート・サイト、
Defect・List、iFix・List(Edge)につきましては、次ページ以降で紹介させて頂きます。
7
WASサポート・サイト
Technotesや既知の障害情報を検索可能
推奨される修正プログラム、
FixPackのダウンロード
情報の検索
Technotes、修正プログラムの情報
InformationCenter、RedBook
IBM Support Assistant
8
＜WASサポート・サイト＞
Technotesや既知の障害情報を検索する事が出来ます。
・Technotesや修正プログラム情報
・情報の検索
・推奨される修正プログラム、FixPackのダウンロード
・InformationCenter、RedBook
8
Defect・List（WAS） / iFix ・List（Edge）
Defect・List（WAS）
RefreshPack・FixPackによる機能追
加・修正内容の一覧表示
FixPackに対する、Defect Listを一覧表示
iFix・List(Edge)
iFixによる修正内容の一覧表示
バージョン毎に修正/不具合の
概要、APAR番号が表示
9
Defect・Listでは、RefreshPack・FixPackによりどのような機能追加や修正が行われたのかを確認する事が
出来ます。iFix・List(Edge)では、EdgeのFix情報を日本語で確認する事が出来ます。FixPack適用の際は、
是非、ご参考にして下さい。
9
１.問題判別の心得
１－１ 問題判別の基本
１－２ 情報収集・問題判別ツール
10
10
Edgeの情報収集 (1/3)
情報収集ツール lbpd
Dispatcher用問題判別基本情報収集ツール
<EDGE_ROOT>/lbディレクトリ下にlbpmr.tar.Zが作成される
lbpmr.tar.Zに含まれるもの
¾
¾
¾
lbpd実行結果（lbinfo.txt）
<EDGE_ROOT>/lb/logs/下の
ログファイル全て
<EDGE_ROOT>/lb/
configurations/dispatcher/下の
構成ファイル全て
lbpdの中で採取している情報 < AIXの例>
[/opt/ibm/edge/lb/servers/bin]# ./lbpd
Running java -version................................Done.
Running netstat -ni..................................Done.
Running netstat -nr..................................Done.
Running lslpp -l.....................................Done.
Running no -a........................................Done.
Running arp -a.......................................Done.
Running dscontrol executor status....................Done.
Running dscontrol executor report....................Done.
Running dscontrol cluster report :...................Done.
Running dscontrol cluster status :...................Done.
Running dscontrol port report ::.....................Done.
Running dscontrol port status ::..................... Done.
Running dscontrol server report ::...................Done.
Running dscontrol server status ::...................Done.
Running dscontrol highavailability status............Done.
Running dscontrol manager report.....................Done.
Running dscontrol file save ibmpmr.cfg force.........Done. 11
Edgeで問題発生時に情報を収集するツールとしてlbpdコマンドがあります。実行すると、
<EDGE_ROOT>/lbディレクトリ下にlbpmr.tar.Zファイルが作成されます。このファイルにはlbpd実行結果、ロ
グファイル、構成ファイルが含まれます。
11
Edgeの情報収集 (2/3)
現行構成ファイル
dscontrol file save <ファイル名>
¾
¾
[AIX/Linux]
[Windows]
<EDGE_ROOT>/lb/servers/configurations/dispatcher
<EDGE_ROOT>¥lb¥servers¥configurations¥dispatcher
[/]# dscontrol executor report
Dispatcherのバージョン
Dispatcherが稼働している場合
稼働していない場合
¾
¾
¾
¾
¾
dscontrol executor report
[AIX]
lslpp –l | grep ibmlb
[Linux]
rpm -qa | grep ibmlb
[Solaris] pkginfo -l ibm
[Windows] コントロールパネルのプログラムの追加と削除
Executor 報告書:
---------------バージョン・レベル ............................ 07.00.00.00
- 20080813-182443 [wsbld178]
開始から受信したパケットの合計 ................ 119
非転送先アドレスに転送されたパケット ..........
119
マシンでローカルに処理されたパケット .......... 0
連結サーバーに送信されたパケット .............. 0
Dispatcherと割振り先サーバーのネットワーク情報
設定
ルーティング
接続テーブル
インターフェース
[Unix] netstat –in
[Windows] ipconfig –all
[Unix] netstat –rn
[Windows] route print
[Unix] netstat –an
[Windows] netstat –an
[UnixOnly] ifconfig –a
12
Edgeで問題判別の際に収集すべき情報には、現行構成ファイル、バージョン、ネットワーク情報、ログファ
イル、ネットワーク・トレースがあります。現行構成ファイル、バージョン、ネットワーク情報は、上記のコマンド
を実行することで取得出来ます。
12
Edgeの情報収集 (3/3)
ログファイル
<EDGE_ROOT>¥lb¥servers¥logsディレクトリ下のログファイル
¾
ハイ・アベイラビリティの問題
z
z
¾
アドバイザーの問題
z
ログレベル５のアドバイザー・ログ
スクリプトファイル
ログレベル５のhamon.log
ログレベル５のreach.log
<EDGE_ROOT>¥lb¥servers¥binディレクトリ下のスクリプト・ファイル
ネットワーク・トレース
[AIX]
¾
[AIX]
¾
ユーザー・トラフィックに問題がある場合
iptrace -a -s <クライアントIP> -d <クラスター・アドレス> -b <出力ファイル名>
Heartbeatに問題がある場合
iptrace –abp <HeartBeat使用ポート> <出力ファイル名>
[Linux] tcpdump -w <出力ファイル名>
[Windows]snifferやWireShark(旧名称：Ethereal)など
13
ログファイルは必要に応じてログ・レベルを変更し、最終的にログなどから問題を切り分ける事が出来ない
場合は、ネットワークトレースを採取することがあります。ネットワークトレースは、上記のコマンドを実行する
ことで取得出来ます。
AIX環境でのIPトレースの使用方法につきましては、以下をご紹介させて頂きます。
・Information Center - - 「iptrace デーモン」
http://publib.boulder.ibm.com/infocenter/systems/scope/aix/index.jsp?topic=/com.ibm.aix.cmds/doc/aix
cmds3/iptrace.htm&tocNode=toc:com.ibm.aix.doc/aix/2/0/8/53/
13
IHSの情報収集
バージョン
[Unix]
[WINDOWS]
<IHS_ROOT>/bin/apachectl –v
<IHS_ROOT>/bin/Apache.exe –v
# <IHS_ROOT>/bin/apachectl –v
Server version: IBM_HTTP_Server/7.0.0.0 (Unix)
Server built: Aug 6 2008 17:10:22
<IHS_ROOT>/bin/versionInfo.bat(sh)
# <IHS_ROOT>/bin/versionInfo.sh
<<途中省略>>
インストール済み製品
-------------------------------------------------------------------------------名前
IBM HTTP Server
バージョン
7.0.0.0
ID
IHS
ビルド・レベル
sup0833.39
ビルド日
8/20/08
アーキテクチャー
Intel (32 bit)
-------------------------------------------------------------------------------インストール状況レポートの終了
--------------------------------------------------------------------------------
ログファイル・ディレクトリー
設定ファイル
デフォルトは、<IHS_ROOT>/logs
<IHS_ROOT>/conf/httpd.conf
14
IHSで問題判別の際に収集すべき情報には、バージョン、ログ、設定ファイルがあります。バージョンは、
Unix環境では<IHS_ROOT>/apachectl –vコマンドにて、Windows環境では<IHS_ROOT>/bin/Apache.exe –
vコマンドを実行することで、IHSのバージョンと対応するApacheのバージョンが表示されます。また、IHSの
バージョン情報は、<IHS_ROOT>/bin/versionInfo.bat(sh)コマンドでも確認できます。ログファイルは
<IHS_ROOT>/logs以下に存在し、設定ファイルは<IHS_ROOT>/conf/httpd.confに存在します。
14
WASの情報収集
情報収集ツール <WAS_PROFILE_ROOT>/bin/collector.sh(.bat)
<Hostname>-<Cellname>-<Nodename>-<Profilename>-WASenv.jarファイル
に出力
¾
¾
¾
¾
¾
¾
¾
¾
-summaryオプションで、一つのテキストファイルで出力
¾
¾
¾
¾
¾
ホスト、ノード名
インストールディレクトリ
WASのバージョン
Javaのフルバージョン
OSのバージョン
Collectorコマンドはプロファイル単位で実行
バージョン
コレクターツールのログ
<WAS_ROOT>と<WAS_PROFILE_ROOT>以下のbin、config、logs、profiles、propertiesディレク
トリ以下のファイルのコピー
OS情報
Java 情報
WAS情報 (<WAS_ROOT>以下のディレクトリ構造とファイルが記載)
コレクターツールが実行したシェルスクリプト (バッチファイル) の実行情報
MQ情報（WebSphereMQまたは組み込みメッセージングフィーチャーをインストールした場合）
JAR ファイルのマニフェスト
versionInfoコマンド
ログファイル、設定ファイル（→後述）
15
WASで問題発生時に情報を収集するツールとしてcollectorコマンドがあります。WAS V7環境で、このコマ
ンドを実行すると、当コマンドが非推奨である旨が警告されますが、ISAは2009年3月時点では、あらゆる環
境において利用可能なツールとなっておらず、現時点ではcollectorが最も有力なツールとなります。IBM
サービスライン（パスポート・アドバンテージ）を利用の際は、担当者の指示に従い、適切な収集ツールを選
択してください。
collectorコマンドを実行すると上記の情報を一つのJARファイルにアーカイブします。実際のcollectorコマ
ンドは、<WAS_ROOT>/binにあり、取得対象とするプロファイル名や、出力ファイル名などが指定できますが、
<WAS_PROFILE_ROOT>/bin配下にあるcollectorコマンドを実行することでこれらが省略可能です。
collectorコマンドは、WASのインストールディレクトリ以外で実行する必要があり、出力先を指定しない場合
はカレントディレクトリにJARファイルが出力されることを念頭に、適切なディレクトリから
<WAS_PROFILE_ROOT>/bin/collector.sh(.bat)を実行します。また、collectorコマンドに-summaryオプショ
ンをつけて実行させると、Collector_Summary.txtという名前のテキストファイルでサマリー情報を出力します。
バージョンの確認は、ログファイルやcollectorのサマリー情報以外に、
<WAS_PROFILE_ROOT>/bin/versionInfo.sh(.bat) コマンドで確認することが出来ます。
その他、WASで問題判別の際に収集すべき情報には、ログ、設定ファイルがございますが、次ページ以降
でご説明させて頂きます。
15
MustGather
WASの問題判別のサポートサイト
発生した問題に対する情報収集の作業方法などを掲載
MustGather: Read first for WebSphere Application Server
http://www-1.ibm.com/support/docview.wss?rs=180&uid=swg21145599
問題の種類、発生コンポーネント
のリストから選択
問題の種類ごとに
取得すべき情報と作業方法を記載
Technical supportからの検索
結果としてリストされ、該当するリン
クを選択
16
その他、問題が発生した際に参考にするサポートサイトとして、MustGather：Read first for all WebSphere
Application Serverがあります。このページでは、問題の種類や問題が発生したコンポーネントがリストになっ
ており、問題の種類に応じて取得すべき情報収集の作業方法などが示されております。問題判別を行う際
には参考にして下さい。
(例)問題の種類、発生コンポーネント
・100% CPU Usage
・Classloader
・DB Connections/Connection Pooling
・EJB
16
IBM Support Assistant(ISA)
IBM製品に関する課題を解決するためのツール
関連するコンポーネントは以下の通り
ISAエージェント・マネージャー
ISAエージェント
ISAワークベンチ
マシンC
マシンB
ISA
エージェント
アプリケーション・
サーバー
ISA
エージェント・
マネージャー
Web
サーバー
ISA
エージェント
マシンD
ISA
エージェント
マシンA
アプリケーション・
サーバー
ISA
ワークベンチ
17
IBM Support Assistant(ISA)とは、WebSphere製品だけにとどまらず、多くのIBM製品に関する課題を解決
するためのサポート・ツールです。 WAS製品導入CDもしくは、次のリンク先
(http://www.ibm.com/software/support/isa/)より導入することが出来ます。
ISAに関連するコンポーネントとその役割は以下の通り
・ISAワークベンチ
クライアント・サイドのアプリケーションで、ISAに関する操作を行うコンソール
・ISAエージェント
ワークベンチは、エージェント・マネージャーを通じてエージェントを知りますが、操作自体はワークベンチ
から直接行われます。
・ISAエージェント・マネージャー
ISAエージェントの情報を保管、管理するマネージャー
17
その他問題判別ツール一覧
代表的な解析対象資料に対する問題判別ツール一覧
これらツールの一部はISAのプラグインとして組み込まれており、ISAからの起動
が可能
解析対象資料
設定方法
説明
冗長ガーベッジ
コレクション
（verbose:gcログ）
管理コンソール、または、 GC状況のトレース
JVM引数で設定する
JavaDump（javacore)
デフォルトで、JVMのク
ラッシュ時やQUIT(kill 3)シグナルを受け取った
ときに生成する
HeapDump
デフォルトで
OutOfMemory発生時に
自動生成する
(クラッシュ時にも生成す
るように環境変数で設定
変更可能)
解析ツール
◎
GCMV（ISAから起動可能）
○
GC Collector
△
JVMに関するダンプ情報。 IBM Thread and Monitor
OS情報、環境変数、稼
Dump Analyzer for Java
動する全スレッドのダン
Technology
プ情報など
ThreadAnalyzer
(ISAから起動可能)
JVMが使用するヒープ上
に存在する全liveオブ
ジェクトのダンプ情報
お勧め度
PMAT(ISAから起動可能)
◎
○
HeapAnalyzer
◎
HeapRoots
○
MDD4J(ISAから起動可能)
△
18
問題判別時に使用するツールの一覧を纏めました。表からもわかるようにISAを使用することにより、冗長
ガーベッジコレクション・JavaDump・HeapDump等の問題判別ツールを登録することができます。
PMAT：IBM Pattern Modeling and Analysis Tool for Java Garbage Collector
EVTK
：Extensible Verbose Toolkit
MDD4J：Memory Dump Diagnostic for Java
その他、ISAに登録されている以外のツールにつきましては、以下をご参照下さい。
・GC Collector
http://www.alphaworks.ibm.com/tech/gcdiag
・IBM Thread and Monitor Dump Analyzer for Java Technology
http://www.alphaworks.ibm.com/tech/jca
・HeapAnalyzer
http://www.alphaworks.ibm.com/tech/heapanalyzer
・HeapRoots
http://www.alphaworks.ibm.com/tech/heaproots
18
２.問題判別
２－１ ログ、トレース
２－２ JVM問題判別
２－３ 症状別問題判別
19
19
各コンポーネントで取得できるログ
Edge server.log、manager.log、…etc
IHS access.log、error.log
プラグイン http_plugin.log
WAS JVMログ、プロセスログ、HTTPトランスポートログ、…etc
HTTP(S)
Edge
Edge
HTTP(S)
WebServer
WebServer
Plug-in
Module
server.log、manager.log
access.log、error.log
HTTP(S)
Plug-in
Config
XML file
Application
Application
Server
Server
連携
DB
JDBCトレースログ
SystemOut.log、SystemErr.log、
native_stdout.log、native_stderr.log、
http_access.log、http_error.log、
activity.log、<process>_<time>.log
http_plugin.log
20
ログは問題判別の基本となるものであり、出力する製品や階層に応じてさまざまなログが出力されます。こ
の章では、EdgeからWASに至るまでのログについて紹介します。
ブラウザから実行されるリクエストはまずEdgeからIHSに割り振られ、そのリクエストがWASに処理を委ねる
ものとプラグインが判断した場合、プラグインはそのリクエストをWASに渡します。WAS内で処理されたリクエ
ストはプラグイン、IHSを通ってブラウザに戻されます。実際に記録されるタイミングは、各コンポーネントに
よって違うため、問題判別を行う際には注意が必要です。
また、問題判別をされる際には、クライアントに近い方から順番に問題の切り分けを実施して下さい。
20
Edgeのログ
Load Balancerのログは循環ログ
サイズがオーバーしたら古いログから上書き
ログ・サイズは変更可能
ログの種類
server.log
manager.log
使用advisor名_ポート.log
subagent.log
hamon.log
reach.log
¾
¾
¾
¾
¾
¾
dsserverの活動の記録、発行したコマンド等の情報
managerの活動記録等
使用するadvisorに関する情報
SNMP subagentに関する情報
high availabilityに関する情報（Primary, Backupの両方）
reach advisorがとばしたping情報等
21
上記のログは、コマンドdscontrol loglevel <0～5> にて書き込む情報量を変更することが可能です。
ログレベルを0～5まで変更することが出来ます。ログレベルが3以上の場合は、最大サイズを設定すること
が推奨されます。指定のサイズに達すると、ファイルの先頭から以前のログ項目を上書きします。ログにはタ
イムスタンプが記録されるため、書き込まれた順番は判断可能です。なお、ログのデフォルトのサイズは１
MBで、現在の値よりも小さいものには設定できません。
(※) LoadBalancerのログは問題判別用ですので、常時ログレベルを5にして運用する事は一般的ではあり
ません。ログレベルを高くするとパフォーマンスが悪くなります。
Load Balancerを再起動したときに、前回使用していたログファイルに.bak拡張子を付加して保存し、新し
いログファイルが作成されます。ログを保存したい場合は、再起動する前に、.bakを保存する事をお奨め致
します。
21
IHSのログ
access.log
IHSに届いたリクエストの処理記録
LogFormatディレクティブで、記録項目はカスタマイズ可能（→後述）
出力先はディレクティブで指定（管理コンソールからも可能）
error.log
IHSのリクエスト、もしくは処理中に発生したエラーやwarningを記録
LogLevelディレクティブで、ログレベルは変更可能（→後述）
出力先はディレクティブで指定（管理コンソールからも可能）
22
IHSで取得されるログは、access.logとerror.logの2つになります。
access.logは、クライアントからIHSに届いたリクエストに対するリプライの記録であり、アクセス数の集計によ
く用いられるログです。access.logに記述される内容は、LogFormatディレクティブでカスタマイズが可能です。
error.logは、リクエストもしくはIHSがリクエストを処理する中で発生したエラーやWarningを記録するログで
す。出力される内容はLogLevelディレクティブで変更することが可能です。
これら2つのログはデフォルトでは<IHS_ROOT>/logsに出力されますが、CustomLogやErrorLogディレク
ティブで出力先やログ名を変更することも可能です。またV6からはデプロイメントマネージャの管理下にあ
れば、管理コンソールから出力先を変更することも可能です。
問題判別をされる際には、access_logでのリクエストのHTTPステータスやレスポンスタイム、error_logにエ
ラーメッセージが出力されていないか等を確認して下さい。
22
IHSアクセスログのカスタマイズ
LogFormatディレクティブ
指示子でもってログに記述する内容を定義
各々のフォーマットに識別のための名前をつけ、そのフォーマット名で
ログに結びつける
httpd.conf
LogFormat "%h %l %u %t ¥"%r¥" %>s %b ¥"%{Referer}i¥" ¥"%{User-Agent}i¥"" combined
LogFormat "%h %l %u %t ¥"%r¥" %>s %b" common
LogFormat "%{Referer}i -> %U" referer
LogFormat "%{User-agent}i" agent
フォーマット名commonを
CustomLog logs/access.log common
ログのフォーマットに指定。
ログの出力ディレクトリ、ファイル名を指定。
IHSのレスポンスタイムはデフォルトでは記載がないので注意
¾
％Dもしくは％TをLogFormaｔに追加
手動でレスポンスタイムをログに記録させる設定が必要。
httpd.conf
LogFormat “%h %l %u %t ¥”%r¥“ %>s %b %D ” common
23
アクセスログのカスタマイズは、LogFormatディレクティブで行います。デフォルトでは以上4パターンの
LogFormatが指定されており、それぞれに名前が付けられています。LogFormatディレクティブの最後に指
定されている内容（上記のcombined、common、referer、agent）がそれぞれのフォーマット名になります。アク
セスログの出力先はCustomLogで指定しますが、その際、最後にフォーマット名を記述します。そうすること
で、指定されたフォーマットでアクセスログに出力されます。
LogFormatでは、ログに記述する内容を指示子と呼ばれる特殊記号で表現します。デフォルトで指定され
ているLogFormatではIHSのレスポンスタイムは記録されません。IHSのレスポンスタイムを記録するには、
LogFormatディレクティブに%Dもしくは%Tを追加する必要があります。％Dはマイクロ秒単位、％Tは秒単位
でIHSがリクエストを受け取ってレスポンスを返すまでにかかる時間をアクセスログに記録します。また、リクエ
ストがIHSに入って来た時ではなく、IHSから出て行った時にaccess_logにログが書き込まれます。従いまして、
access_logでは、リクエスト順にログが書き込まれるわけでは無い事をご注意下さい。
問題判別の観点からは、このレスポンスタイム出力を設定される事をお勧め致します。
・IHSのLogFormatディレクティブ
http://httpd.apache.org/docs/2.1/mod/mod_log_config.html#formats
23
IHSエラーログのログレベル
LogLevelディレクティブ
エラーログに記録される内容のレベルを指定
デフォルト：warn
debug,info,notice,warn,error,crit,alert,emergの8種類
httpd.conf
LogLevel debug
error.log
LogLevelをWarnからdebugに変更してIHSを起動したときの例
デフォルトでは記録されないinfoやdebug情報が出力される
[Sat Apr 11 11:47:46 2009] [info] mod_unique_id: using ip addr 9.188.198.192
[Sat Apr 11 11:47:47 2009] [info] mod_unique_id: using ip addr 9.188.198.192
[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: WebSphere Plugins loaded.
[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: --------------------Plugin Information---------------------[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: Bld version: 7.0.0
[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: Bld date: Nov 11 2008, 22:32:03
[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: Webserver: IBM_HTTP_Server
[Sat Apr 11 11:47:48 2009] [notice] PLUGIN: mod_was_ap22_http: apache_log_header: ------------------------------------------------------------[Sat Apr 11 11:47:48 2009] [notice] Using config file /opt/IBM/HTTPServer/conf/httpd.conf
[Sat Apr 11 11:47:48 2009] [debug] mod_mpmstats.c(189): mpmstats daemon started (pid 25709)
[Sat Apr 11 11:47:48 2009] [notice] IBM_HTTP_Server/7.0.0.0 (Unix) configured -- resuming normal operations
[Sat Apr 11 11:47:48 2009] [info] Server built: Aug 6 2008 17:10:22
24
[Sat Apr 11 11:47:48 2009] [debug] worker.c(1837): AcceptMutex: sysvsem (default: sysvsem)
[Sat Apr 11 11:47:48 2009] [notice] Core file limit is 0; core dumps will be not be written for server crashes
IHSのエラーログに記録される内容は、LogLevelディレクティブで指定することが出来ます。ログレベルに
はdebug、info、notice、warn、error、crit、alert、emergの8種類がありdebugからemargになるにつれ重要度が
高くなります。ログレベルはデフォルトではwarnに設定されているため、warnより上の重要度の情報が記載さ
れます。さらにdebugやinfoといった詳細な情報をログに記録させたい場合には、LogLevelディレクティブの
指定をdebugに変更すると、全ての情報がエラーログに記載されるようになります。問題判別を行う際には、
このログレベルを上げて下さい。
24
プラグインのログ
http_plugin.log
プラグインの処理内容を記録
WebサーバーとWAS間の通信に問題があるときに参照
plugin-cfg.xmlファイル内でログに関する設定を行う (→後述)
¾
設定は管理コンソールからも実施可能
plugin-cfg.xml
<Config ASDisableNagle="false" AcceptAllContent="false"
AppServerPortPreference="WebserverPort" ChunkedResponse="false" FIPSEnable="false"
IISDisableNagle="false" IISPluginPriority="High" IgnoreDNSFailures="false" RefreshInterval="60"
ResponseChunkSize="64" VHostMatchingCompat="false">
<Log LogLevel="Error" Name="/opt/IBM/HTTPServer/Plugins/logs/webserver1/http_plugin.log"/>
ログレベル
ログの出力先
管理コンソール
「サーバー」→「Webサーバー」→
<WebServer name>→「プラグイン・プロパティー」 25
プラグインが出力するログがhttp_plugin.logになります。http_plugin.logはプラグインの処理内容が記録され
ており、WebサーバーとWASとの通信に問題があると思われたときに参照して問題解析を行ってください。
プラグインログに関するログレベルや出力先の設定はplugin_cfg.xmlで記載されており、plugin_cfg.xml内の
LogLevel、Nameといった設定箇所を編集することで変更することが可能です。またV6からは管理コンソール
からの「プラグイン・プロパティー」からも設定が可能です。管理コンソールから設定を行うためには、Web
サーバーがデプロイメントマネージャの管理下である必要があります。またplugin-cfg.xmlの位置は、IHSの
設定ファイルであるhttpd.confで指定します。
25
プラグインログのログレベル
Trace （→後述）
Stats
プラグインの処理中に発生したエラーを記録
Debug
プラグインの処理中に発生したエラーとWarningを記録
Error（デフォルト）
リクエストに対し選択されたサーバー、ロードバランシング情報を記録
Warn
リクエストを受けた際にプラグインが行った全過程の詳細が記録
リクエストの処理中に実行された重大なステップが記録
Detail
リクエストおよびリプライに関するすべての情報を記録
http_plugin.log
[Sat Apr 11 12:23:49 2009] 00006903 f461ab90 - STATS: ws_server_group: serverGroupCheckServerStatus:
Checking status of WSClientIse135Custom_server1, ignoreWeights 0, markedDown 0, retryNow 0, retryInSec --,
wlbAllows 1 reachedMaxConnectionsLimit 0
[Sat Apr 11 12:23:49 2009] 00006903 f461ab90 - STATS: ws_server: serverSetFailoverStatus: Server
WSClientIse135Custom_server1 : pendingRequests 0 failedRequests 0 affinityRequests 0 totalRequests 1.
26
プラグインログの出力レベルは、デフォルトではErrorになっています。つまり、エラーが発生しない限り、プ
ラグインがリクエストを正しく割り振ってもその記録は残りません。より詳細な記録をプラグインログに記載さ
せるためにはログレベルを変更する必要があります。
ログレベルにはError以外にも、Debug、Detail、Warn、Stats、Traceがあり、Traceがもっとも詳細に処理内
容が記載されます。Statsではプラグインの割り振り先やロードバランシング情報が記載されます。IHSとWAS
が1対N構成時に、IHSのプラグインが割り振ったサーバーを確認したい場合には一般的にはStatsを設定し
ます。
26
プラグインログのトレース
ログレベルを「Trace」に設定
リクエストを受けた際にプラグインが行った全過程を記録
http_plugin.log
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: ws_common: websphereShouldHandleRequest: trying to match a route for:
vhost='ise135.makuhari.japan.ibm.com'; uri='/XATestWeb/index3.html'
仮想ホスト、URIを比較し、
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DEBUG: ws_common: websphereVhostMatch: Found a match '*:80' to 'ise135:80' in
VhostGroup: default_host with score 1, exact match 0
WASに処理を渡すことを判断
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DEBUG: ws_common: websphereUriMatch: Found a match '/XATestWeb/*' to
'/XATestWeb/index3.html' in UriGroup: default_host_WSClientCluster_URIs with score 11, exact match 11
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: mod_was_ap22_http: as_translate_name: WebSphere will handle:
/XATestWeb/index3.html
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: lib_htrequest: htrequestSetMethod: Setting the method |GET|
WASに送るリクエストのヘッダ作成
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: lib_htrequest: htrequestSetURL: Setting the url |/XATestWeb/index3.html|
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - STATS: ws_server_group: serverGroupCheckServerStatus: Checking status of
WSClientTitanCustom_server2, ignoreWeights 0, markedDown 1, retryNow 1, retryInSec -121, wlbAllows 0 reachedMaxConnectionsLimit 0
リクエストを処理するサーバーの情報を取得。
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: ws_server_group: lockedServerGroupUseServer: Server
サーバーにアクセスし、Weightを1減らす
WSClientTitanCustom_server2 picked, weight -1.
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: ws_server_group: serverGroupIncrementConnectionCount: Server
WSClientTitanCustom_server2 picked, pendingConnectionCount 1 totalConnectionsCount 1.
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DEBUG: lib_htrequest: htrequestWrite: Writing the request reqInfo is OK:
WASにリクエストを送信し、レスポンスを受信する
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: GET /XATestWeb/index3.html HTTP/1.1
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: ws_common: websphereExecute: Wrote the request; reading the response
（その際のヘッダの情報を取得）
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: lib_htresponse: htresponseRead: Reading the response: 97bf674
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: HTTP/1.1 200 OK
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: Date: Sat, 11 Apr 2009 03:38:39 GMT
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: mod_was_ap22_http: cb_write_headers: In the write headers callback
クライアントに返すレスポンスのヘッダ作成し、
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - TRACE: mod_was_ap22_http: cb_write_headers: Adding header Date value is Sat, 11 Apr
プラグインは処理を終了
2009 03:38:39 GMT
27
[Sat Apr 11 12:38:39 2009] 00006923 f641db90 - DETAIL: ws_common: websphereEndRequest: Ending the request
プラグインログのレベルをTraceに設定すると、プラグインが処理した詳細な内容がログに記載されますの
で、問題判別時には非常に有用です。上記のログは、プラグインログのレベルをトレースにしたときのログを
抜粋して見やすくした例です。リクエストがプラグインに来てから、仮想ホストやURIを比較しWASに処理を
渡すことを判断したことを示す記述や、リクエストヘッダの生成、リクエストを処理するサーバーの選択、リク
エストの送信とレスポンスの受信、さらにクライアントに返すレスポンスのヘッダを作成してクライアントに処理
を返すまでの内容を確認することが出来ます。
27
WASのログ
JVMログ（SystemOut.log / SystemErr.log）
プロセスログ(native_stdout.log / native_stderr.log)
エラー情報を発生時に自動で記録される
サポートセンター、開発部門が障害対応時に見るログ
HTTPトランスポートログ（http_access.log / http_error.log）
ネイティブコードやJVM自身の出力が書き込む情報
FFDCログ（<process_name>_<timestamp>.txt）
JVMの標準出力、標準エラー出力
アプリケーションの挙動やプロセスの稼動状況
WebコンテナーのHTTPトランスポートに対するアクセスを記録するロ
グ
IHSを介さないアクセスに対するアクセスログ、エラーログ
IBM保守ログ（activity.log）
JVMの詳細な情報を記録したログ
showlogコマンドを使用
28
WASで取得できるログは、以上になりますので、ご確認下さい。
・JVMログ
SystemOut.log、SystemErr.logという名前で出力され、アプリケーションの挙動やプロセスの稼動状況を記
載されます。
・プロセスログ
native_stdout.log、native_stderr.logという名前で出力され、ネイティブコードやJVM自身の出力が記載され
ます。
・FFDC(First Failure Data Capture)ログ
全てのシステムエラーを発生時点で自動的に記録されるもので、サポートセンターや開発部門が障害対
応時に確認するログです。
・HTTPトランスポートログ
WebコンテナーのHTTPトランスポートに対するアクセスを記録するログで、IHSを介さないアクセスに対す
るアクセスログとエラーログです。
・IBM保守ログ
JVMログにさらに詳細な情報を記録したログで、バイナリファイルのためエディターで開くことはできません。
確認するためにはshowlog.bat(sh)というコマンド実行が必要になります。
28
JVMログ
SystemOut.log / SystemErr.log
問題判別を行う上で、最も重要なログ
アプリケーションの挙動やプロセスの稼動状況が記載されているログ
アプリケーションサーバー、ノードエージェント、デプロイメントマネージャなど各プロセ
ス単位で存在
「サーバー」→「アプリケーションサーバー」→<server_name>
→「ロギングおよびトレース」→「JVMログ」
出力先ファイル名
ファイルのフォーマット（基本or拡張）
＜ログファイルの循環＞
ファイルサイズ（指定サイズが来たとき）や
時間（指定時間に達したとき）で新規ファイルを
作成可能
アプリケーション内のprint文をログに書き込むか、
また、その文を指定したフォーマットに従って
29
フォーマットするか（デフォルト両方ON）
JVMログは、アプリケーションの挙動やプロセスの稼動状況が記載されているログで、問題判別を行う上で
もっとも重要なログの一つです。JVMログは各アプリケーションサーバー、ノードエージェント、デプロイメント
マネージャなど、各プロセス単位で<WAS_PROFILE_ROOT>/logs/<process_name>ディレクトリ以下に出力
されます。JVMログに関する設定は管理コンソールから行います。
29
JVMログに出力されるメッセージ
メッセージID
メッセージを発行したコンポーネントやその重要度を示す
エラーメッセージが出た際、メッセージIDでInformation Centerを検索
SystemOut.log
[09/04/08 15:26:43:678 JST] 00000000 WsServerImpl A WSVR0001I: e-business の
ためにサーバー server1 が開かれました
メッセージID
最初の4文字（もしくは5文字）がコンポーネントを示す
続く数字がそのコンポーネントでメッセージを識別するための番号
最後の1文字が重要度（I=情報、W=警告、E=エラー）を示す
Infocenterから 「参照」→「トラブルシューター」
→「メッセージ」より、
メッセージIDとその内容と対応を見ることができる
30
JVMログに出力されるメッセージにはメッセージIDと呼ばれるIDが付けられており、メッセージが分類できる
ようになっています。メッセージIDは最初の4文字（もしくは5文字）がコンポーネントを示しており、続く数字
がそれらのメッセージを識別するための番号、最後の一文字が重要度を示しています。重要度は、Iが情報、
Wが警告、Eがエラーを示しており、一番重要度が重いのはエラーです。
WAS V7.0のInformationCenterではメッセージIDごとにその内容と対応を確認することが出来ます。出力さ
れたメッセージに関して情報が知りたい場合は、 InformationCenterでメッセージIDをもとに検索して下さい。
・WAS V7.0 InformationCenter
http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/index.jsp
30
プロセスログ
native_stdout.log / native_stderr.log
ネイティブコードやJVM自身の出力が書き込まれるログ
SystemOut.logへの出力は、プロセスログへは出力されない（WAS V5より）
JVMのverbose:gcを設定した場合、その出力はnative_stderr.logに記録。
循環はしないが、JVMログに比べファイルの増加率は小さい。
「プロセス定義」→「Java仮想マシン」
「ロギングおよびトレース」→「プロセスログ」
出力先ファイル名
冗長ガーベッジコレクションをONにすると、
GCの詳細な情報がnative_stderr.logに出力される
31
プロセスログはネイティブコードやJVM自身の出力が書き込まれるログであり、WASV5からは
SystemOut.logの出力はプロセスログには出力されなくなりました。JVMログと違い、プロセスログには循環さ
せるための仕組みは組み込まれていませんが、JVMログに比べ、ファイルの増加率は非常に小さいです。
また、JVMのverbose:gcの設定をした場合、GCの結果の出力はデフォルトではnative_stderr.logに記載され
ます。ガーベッジコレクションの状況を確認されたい場合には、当ログを確認して下さい。
31
FFDCログ（<process_name>_<timestamp>.txt）
First Failure Data Capture
全てのシステムエラー情報を発生時点で自動的に記録するツール
サポートセンターや開発部門が障害時に見て分析
<WAS_PROFILE_ROOT>/logs/ffdcディレクトリに出力
<process name>_exception.log
サーバー起動中に発生した例外情報の統計を管理する
ffdcディレクトリに作成
32
FFDCとはFirst Failure Data Captureの略で、全てのシステムエラー情報を発生時点で自動的に記録する
ツールになります。このツールによって作成されたFFDCログは、サポートセンターや開発部門が障害時に
確認して分析を行うためのものです。ログはプロセス単位のディレクトリではなく、
<WAS_PROFILE_ROOT>/logs/ffdcというディレクトリに出力されます。ファイル名は
<process_name>_<timestamp>.txt（例えば、server1_5c655712_04.11.18.2327.48_0.txt）となります。また、
サーバー起動中に発生した例外情報の統計を管理する<process name>_exception.logというログファイルも
ffdcディレクトリに作成されます。
32
HTTPトランスポートログ
http_access.log / http_error.log
WebコンテナーのHTTPトランスポートに対するアクセスの記録
デフォルトでは取得されない
¾
Webサーバーを介さない場合に有用なアクセスログ
「Webコンテナトランスポートチェーン」→<Transport_name>→
「HTTPインバウンドチャネル」
「サーバー」→「アプリケーションサーバー」→
<Server_name>→「HTTPエラーおよびNCSAアクセスロギング」
サーバーの起動時に
ロギングのサービスを使用可能にする
指定したトランスポートに対して
ロギングを使用可能にする
33
HTTPトランスポート・ログはアプリケーションサーバーのWebコンテナーのHTTPトランスポートに対するア
クセスを記録するログで、Webサーバーのアクセスログに相当するものになります。これはWebサーバーを介
さないアクセスに対して、Webサーバーのアクセスログの代わりとなるログです。ファイル名はhttp_access.log
およびhttp_error.logで、JVMログと同じディレクトリに出力されます。
HTTPトランスポートのログはデフォルトでは取得されないので、取得するためには設定を変更する必要があ
ります。
管理コンソールの「サーバー」→「アプリケーション・サーバー」からアプリケーションサーバーを選択し、
「HTTPエラーおよびNCSAアクセス・ロギング」を選択します。 設定画面では、アクセスロギングやエラーロ
ギングを使用可能にする、といった項目にはチェックが付いていますが、「サーバー始動時にサービスを使
用可能にする」にチェックが付いていませんので、チェックを入れます。他にもファイルの最大サイズや
フォーマット（共通（Common）or結合（Combined））、ファイル名などはここで指定します。
実際にどのHTTPトランスポートのリクエストおよびエラーをロギングするかの定義は、チャネルに対して行
います。アプリケーションサーバーのページより、 「Webコンテナー・トランスポート・チェーン」で該当トランス
ポート・チェーンを選択し、「HTTPインバウンド・チャネル」をクリックします。設定画面の一般プロパティーの
下の「アクセス・ロギングおよびエラーロギングを使用可能にする」にチェックを付けると、このチャネルに対し
てリクエストされたアクセスログとエラーログが出力されます。
33
IBM保守ログ
activity.log
JVMログに詳細情報を追加したログ
showlog.bat(sh)を使用して読み取る。
ComponentId:
ProcessId:
ThreadId:
0000004d
ThreadName:
WebContainer : 1
SourceId:
com.ibm.ws.webcontainer.webapp
ClassName:
com.ibm.ws.webcontainer.webapp.WebApp
MethodName:
log
製造者:
製品:
バージョン:
Platform 7.0.0.1 [ND 7.0.0.1 cf010845.08]
ServerName:
TimeStamp:
2009-04-11 12:22:44.369000000
UnitOfWork:
重大度: 3
カテゴリー:
INFO
PrimaryMessage: SRVE0292I: サーブレット・メッセージ - [isclite#isclite.war]:.action:
WebServerDetailForm was null.Creating new form bean and storing in session
ExtendedMessage:
34
IBM保守ログのファイル名はactivity.logという名前でノード単位に作成されます。これは
<WAS_PROFILE_ROOT>/logsディレクトリに出力されます。このIBM保守ログはJVMログに詳細情報を追加
したログで、showlog.bat(sh)コマンドにてactivity.logの内容を確認する事が出来ます。
34
WASのトレース
trace.log
WASコンポーネントの実行時の詳細な記録
障害発生箇所特定の大きな手がかり
稼動中のサーバーでも設定が可能
稼動中のサーバーでトレースの設定を行うには
ランタイムタブを開き、
「ランタイム変更も構成に保管する」をチェックし、
適用する
「サーバー」→「アプリケーションサーバー」→
<Server_name>→「診断トレースサービス」
トレースに書き出すコンポーネントの指定
（詳細は次ページ）
トレース内容をログ出力可能にする
（デフォルトON）
トレースの出力ファイル名、
最大ファイルサイズとヒストリーファイルの最大数
（最大サイズに達したとき、トレースファイルが新規に作成され、
ヒストリーファイル最大数の数だけ残される）
ファイルのフォーマット
（基本or拡張orログアナライザー）
35
トレースを用いると、アプリケーションサーバーや環境内の他のプロセスなど、WASコンポーネントの実行
に関する、より詳細情報を取得することが出来ます。トレースを使用することにより、障害発生箇所特定の大
きな手がかりとなります。トレースの収集は、多くの場合テクニカルサポート担当者の依頼の元で行います。
トレースはJVMログ同様にプロセス単位でディレクトリにtrace.logという名前で取得されます。また稼動中の
サーバーでもトレースの取得を設定することが可能ですので、アプリケーションサーバーを止めることなくト
レースを出力させることが出来ます。
トレースの設定画面は、管理コンソール左メニューから「サーバー」→「アプリケーションサーバー」でサー
バーを選択し、「診断トレースサービス」をクリックすると表示されます。この画面からは、トレースの出力先や
バッファーサイズ、最大ファイルサイズやフォーマットを指定することが出来ます。トレースのログ出力はデ
フォルトでもONになっています。
なお「ログを使用可能にする」は、出力するか否かのみを指定しており、OFFとした場合でも各コンポーネ
ント内では指定されたログ・レベルに応じてトレース機能を通過します。そのため、当機能をOFFにするだけ
ではパフォーマンス上、十分ではありません。むしろ、当機能に関してはONのままとし、ログ・レベルを元に
戻すことをおすすめします。
詳細につきましては、下記テクニカル・フラッシュ「【ご注意ください】WAS: 診断トレースのログ出力設定に
よるパフォーマンスへの影響について」をご参照ください。
http://www-06.ibm.com/jp/domino01/mkt/cnpages1.nsf/page/default-0007CBD1
35
ログ詳細レベルの変更
コンポーネント単位でトレースに出力させるものを指定
下のGUIから選択orログ詳細レベル仕様を直接入力
ログ詳細レベル仕様 <component>=<level>を
直接書き込んでも構わない
ConfigErrorに対し、
レベルfine（詳細-中）を指定
*=info:ConfigError=fine:
com.ibm.ws.http.*=finest
他全てのログレベルはinfo（情報）
com.ibm.ws.http.*に対し、
レベルfinest（詳細-最高）を指定
36
トレース設定画面右の追加プロパティの「ログ詳細レベル仕様」をクリックすると、どのコンポーネントに対し
ログまたはトレースをどのレベルで取得するかを設定することが出来ます。画面下からコンポーネントを選択
しクリックすると、レベルを選択するポップアップが現れますので、レベルを選択すると、それらが上記画面
に反映される仕組みになっています。上記例では、ConfigErrorコンポーネントのレベルを詳細-中(fine)、
com.ibm.ws.http.*に対しレベルを詳細-最高(finest)を指定しています。それらの設定は上記画面に上記の
ように反映されます。なお、デフォルトでは全てのレベルが情報(info)になっています。
また、上記画面からコンポーネントとレベルを<component>=<level>という形で直接書き込んでも構いませ
ん。複数のコンポーネントに対しレベルを指定したい場合は「:」で区切ります。
36
ロギングレベル
OｆｆからAllまでの12段階
ｔrace.logに書き込まれるのは詳細-中（fine）以降を設定した
場合
SystemOut.logログに
書き込まれる情報量が変化
トレースとしてtrace.logに
書き込まれる
ロギングレベル
管理コンソール上の
呼び方
Off
オフ
Fatal
致命的
Severe
重大
Warning
警告
Audit
監査
Info
状況
Config
構成
Detail
詳細-低
Fine
詳細-中
Finer
詳細-高
Finest
詳細-最高
All
すべて
37
コンポーネントに対するログレベルは「オフ」から「すべて」までの12段階です。オフに設定するとログには
何も書き込まれません。レベルはオフがもっとも低く、致命的(fatal)、重大(severe)、警告(warning)、監査
(audit)、情報(info)、構成(config)、詳細-低(detail)、詳細-中(fine)、詳細-高(finer)、詳細-最高(finest)の順に
高くなり、すべて(all)がもっとも高くなります。
このうち詳細-低(detail)まではtrace.logには出力しません。SystemOut.logやIBM保守ログに書き込まれる
レベルが変わります。レベルを詳細-中(fine)以上にすると、そのコンポーネントの内容がtrace.logに出力さ
れます。デフォルトでトレースは取得可能になっていますが、レベルが情報(info)になっているために、デ
フォルトではtrace.logは出力されません。
37
WASのトレースの取得例
例：データベース接続の状況を確認する際のトレース
*=info:WAS.j2c=all:RRA=all:WAS.database=all:Transaction=all
WAS－DB間での問題判別に有用
¾
¾
¾
接続プールの使用状況
リソース参照の情報（アイソレーションレベル・共用接続の有無、など）
トランザクションの開始・終了
コネクションオブジェクトは
接続プール内で、1つは
trace.log
InUse、もう１つはFree。
[09/04/11 18:13:47:049 JST] 00000039 PoolManager 3 release(), Pool contents ==> PoolManager name:jdbc/db2_1
その接続は非共用接続
PoolManager object:867644343
Total number of connections: 2 (max/min 10/1, reap/unused/aged 180/1800/0, connectiontimeout/purge 180/EntirePool)
(testConnection/inteval false/0, stuck timer/time/threshold 0/0/0, surge time/connections 0/-1)
Shared Connection information (shared partitions 200)
No shared connections
Free Connection information (free distribution table/partitions 5/1)
(2)(0)MCWrapper id 5ff15ff1 Managed connection WSRdbManagedConnectionImpl@6ba36ba3 State:STATE_ACTIVE_FREE
Total number of connection in free pool: 1
UnShared Connection information
MCWrapper id 32e332e3 Managed connection WSRdbManagedConnectionImpl@408d408d State:STATE_ACTIVE_INUSE Thread
Id: 00000039 Thread Name: Web
Container : 0 Handle count 0
Total number of connection in unshared pool: 1
38
ここでは実際にトレースを取得した際のサンプルを紹介します。
発生した問題に対してどのようなトレースを取得するかは、サポートセンターの指示や、先述した
MustGatherのサポートサイトなどを参考にして取得を行います。上記はデータベース接続の状況を確認す
る際に有用な、j2cに関するトレースを取得した例になります。このトレース結果から、接続プールの使用状
況や、アイソレーションレベルや共用接続の有無といったリソース参照の情報、トランザクションに関する情
報などがわかりますので、WASとデータベースとの間で問題が発生した際には、問題判別のために非常に
有用です。
38
JDBCトレースログ
JDBCトレースログとは
効果的なケース
JDBCドライバーが出力するトレース
アプリケーションとデータベース間のデータの流れを確認できる
①
②
③
④
⑤
SQLExceptionの原因を探る
ドライバーの内部エラーの原因を探る
JDBC APIの実行時刻とreturn時刻を知る
パラメーターマーカーへの設定値を確認する
分離レベルを確認する
例1：分離レベルを確認する
トレースに出力されていたTransactionIsolationにより確認する（0=None = UR, 2 = CS, 4 = RS, 8 = RR）
[省略] setTransactionIsolation (2) called
例2：JDBC APIの実行時刻とreturn時刻を知る
calledとreturnedを抽出する
更に、ネットワークに要した時間、Driver内の処理時間を算出できる
[省略][Time:2007-05-17-14:05:51.794][省略] executeUpdate (insert into Table (sampleColumn) values (1)) called
[省略][Time:2007-05-17-14:05:51.888][省略] executeUpdate () returned
[省略][SystemMonitor:stop] core: 94.63ms | network: 48.102ms | server: 0.0ms
39
JDBCトレースログとは、JDBCドライバーが出力するトレースになり、ドライバーのプロパティの設定値や実
行しているSQLステートメント・JDBC API等、アプリケーションとデーターベース間のデータの遣り取りの流れ
を確認する事が出来ます。JDBCトレースログを取得する効果的なケースとしては、次が挙げられます。
① SQLExceptionの原因を探る
② ドライバーの内部エラーの原因を探る
③ JDBC APIの実行時刻とreturn時刻を知る
④ パラメーターマーカーへの設定値を確認する
⑤ 分離レベルを確認する
・分離レベルとは
実行するトランザクションが、RDBMSによってどの程度のデータ保証すべきかを定義したもの。
UR: Uncommitted Read(未コミット読み取り)
CS: Cursor Stability(カーソル固定)
RS: Read Stability(読み取り固定)
RR: Repeatable Read(反復可能読み取り)
39
JDBCトレース設定
JDBCドライバーとデータベース間でやり取りされるデータの流れを取得
ドライバーのプロパティー値、実行しているSQLステートメント、実行している
JDBC API等を確認できる
設定指針
以下のようなWASトレース設定では取得できない場合
¾ ドライバーの内部エラー
¾ JDBC APIの実行時刻とreturn時刻
¾ パラメーター・マーカーの設定値
[ibm][db2][jcc][省略][PreparedStatement@39eae493] setInt (1, 1) called
設定方法
[ibm][db2][jcc][省略][PreparedStatement@39eae493] setInt (1, 1) called
[ibm][db2][jcc][省略][PreparedStatement@39eae493] setString (2, COL2-1) called
[ibm][db2][jcc][省略][PreparedStatement@39eae493] setString (2, COL2-1) called
管理コンソールより、JDBC -> データ・ソース -> カスタム・プロパティーを選択し、以下を
設定する
トレースレベルを設定する。
トレースレベルを設定する。
整数値を加算することで、複数のトレースが取得可能。
整数値を加算することで、複数のトレースが取得可能。
(例)1+2=3
(例)1+2=3 (CONNECTION_CALL,STATEMENT_CALL)
(CONNECTION_CALL,STATEMENT_CALL)
trueに設定すると、トレースファイルが上書きされない。
trueに設定すると、トレースファイルが上書きされない。
トレースファイルを設定する。
トレースファイルを設定する。
接続オブジェクト毎にトレースファイルが出力される。
接続オブジェクト毎にトレースファイルが出力される。
(例)_cpds_1
(例)_cpds_1 ,, _cpds_2・・・
_cpds_2・・・
traceFileを設定すると、traceDirectoryは無効になる。
traceFileを設定すると、traceDirectoryは無効になる。
40
JDBCトレースとは、JDBCドライバーとデータベース間でやり取りされるデータの流れを取得したものになり
ます。ドライバーの内部エラー、JDBC APIの実行時刻とreturn時刻やパラメーター・マーカーの設定値を確
認したい場合等に、取得することを検討して下さい。
JDBCトレースは、管理コンソールより、JDBC -> データ・ソース -> カスタム・プロパティーを選択し、
traceLevel、traceFileAppend、traceFile、traceDirectoryを設定して下さい。traceLevelについては、下記リン
ク先をご確認下さい。
・DB2 Information Center - 「サポートされるすべてのデータベース製品に共通の IBM Data Server Driver
for JDBC and SQLJ のプロパティー」
http://publib.boulder.ibm.com/infocenter/db2luw/v9r5/index.jsp?topic=/com.ibm.db2.luw.apdv.java.doc/
doc/r0052038.html
(抜粋)
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_CONNECTION_CALLS= 0x1 (= 1)
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_STATEMENT_CALLS= 0x2 (= 2)
(※)パラメーター・マーカーとは
通常、疑問符 (?) で示され、ステートメント実行中に値が取得されるSQLステートメント内のプレースホル
ダーです。何度も実行する必要のあるSQLステートメントの場合、SQLステートメントを一回だけ準備し、パラ
メーター・マーカーを使って実行時に入力値を置換することにより、照会プランを再利用することが出来ます。
○ SELECT * FROM T1 WHERE C1 = ? ;
× SELECT * FROM T1 WHERE C1 = 100;
・DB2V9.5 InformationCenter - 「パラメーター・マーカー」
http://publib.boulder.ibm.com/infocenter/db2luw/v9r5/index.jsp?topic=/com.ibm.db2.luw.apdv.routines.d
oc/doc/c0020295.html
40
２.問題判別
２－１ ログ、トレース
２－２ JVM問題判別
２－３ 症状別問題判別
41
41
verbose:gc
ガーベッジコレクションの実行状況を記録
native_stderr.logに出力
汎用JVM引数に -Xverbosegclog:<path>/<filename> で変更可能
デフォルトはOFF、管理コンソールにて設定
冗長ガーベッジ・コレクションにチェック or –verbose:gc
アプリケーションサーバー選択し、
「Javaおよびプロセス管理」→「プロセス定義」
→「Java仮想マシン」
冗長ガーベッジ・コレクションにチェック。
もしくは「汎用JVM引数」に-verbose:gc入力
ファイルの出力先をnative_stderr.logから変
更したい場合もここで指定する
42
verbose:gcとはガーベッジコレクションの実行状況をトレースし、native_stderr.logに出力するものです。こ
れを参照することは問題判別のみならずパフォーマンスチューニングにおいても有用です。ただし、デフォ
ルトではOFFになっているためにverbose:gcを有効にするためには設定が必要です。管理コンソールから
「Java仮想マシン」設定画面に移動し、冗長ガーベッジコレクションにチェックを入れるか、汎用JVM引数の
欄に-verbose:gcと入力します。また、出力先はnative_stderr.logですが変更することも可能です。その際は
同じ画面の汎用JVM引数の欄に-Xverbosegclog:<path>/<filename>という形でファイル名のフルパスを記述
します。
42
verbose:gcの出力（GC）
ガーベッジコレクション発生時
native_stderr.log
AFの発生回数
前回のFailure発生からの時間
<af type="tenured" id="2" timestamp="Mar 31 14:49:20 2009" intervalms="73840.418">
<minimum requested_bytes="32" />
<time exclusiveaccessms="0.040" meanexclusiveaccessms="0.040" threads="0" lastthreadtid="0x0746B600" />
<refs soft="2034" weak="12752" phantom="87" dynamicSoftReferenceThreshold="18"
maxSoftReferenceThreshold="32" />
<tenured freebytes="2055680" totalbytes="205617152" percent="0" >
<soa freebytes="0" totalbytes="203561472" percent="0" />
<loa freebytes="2055680" totalbytes="2055680" percent="100" />
Allocationに
</tenured>
必要な容量
<gc type="global" id="49" totalid="49" intervalms="73841.481">
<classunloading classloaders="90" classes="1" timevmquiescems="0.000" timetakenms="5.743" />
<expansion type="tenured" amount="8307200" newsize="213924352" timetaken="0.086" reason="insufficient
free space following gc" />
<finalization objectsqueued="270" />
<timesms mark="322.701" sweep="1.521" compact="0.000" total="330.415" />
<tenured freebytes="64177368" totalbytes="213924352" percent="30" >
<soa freebytes="62252248" totalbytes="211999232" percent="29" />
<loa freebytes="1925120" totalbytes="1925120" percent="100" />
</tenured>
</gc>
<tenured freebytes="64176696" totalbytes="213924352" percent="29" >
<soa freebytes="64176696" totalbytes="213924352" percent="29" />
GC後の容量
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<refs soft="2013" weak="12117" phantom="87" dynamicSoftReferenceThreshold="9"
43
maxSoftReferenceThreshold="32" />
<time totalms="331.115" />
このAllocationFailureに対してかかった時間
</af>
上記はガーベッジコレクションが発生したときのverbose:gcの出力例です。なお、GCポリシーはデフォルト
で、以降の例もすべて同様です。
ガーベッジコレクションはJVMがオブジェクトをヒープに割り当てることができなかったときに発生します。こ
の状態をAllocation Failure(AF)と言います。また、Tenuredとはold領域の事であり、nurseryはnew領域を示
しております。（この出力例ではnurseryは記録されていません）
1行目：afがAllocation Failureの発生、idの数字がJVM起動後にAFが発生した回数を示しています。
Intervalms= 73840.418が前回のAllocationFailureからの経過時間を示しています。上記の例では、
73840ms後に今回(2回目)のAllocation Failureが発生したことを示しています。
2行目：requested_bytes=32byteがAllocationに必要な容量になります。
13行目：このGCのmarkフェーズ（オブジェクトのマーキング）、sweepフェーズ（不要オブジェクトの開放）、
compact（空き領域の整理）の所要時間およびGC全体の所要時間を示しています。上記の例ではcompact
の作業は行っていません。
19行目：GC後の容量を示しています。
24行目：今回のAllocation Failureに要した合計の時間が記録されます。
43
verbose:gcの出力（Compaction）
Compaction発生時
移動したオブジェクトの数とサイズ、Compactionの理由
native_stderr.log
<af type="tenured" id="3" timestamp="Mar 31 14:49:20 2009" intervalms="99.201">
<minimum requested_bytes="12582928" />
<time exclusiveaccessms="0.040" meanexclusiveaccessms="0.040" threads="0" lastthreadtid="0x0746B600" />
<refs soft="2013" weak="12117" phantom="87" dynamicSoftReferenceThreshold="9"
maxSoftReferenceThreshold="32" />
<tenured freebytes="35733624" totalbytes="213924352" percent="16" >
<soa freebytes="35733624" totalbytes="213924352" percent="16" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="50" totalid="50" intervalms="99.862">
<compaction movecount="4767627" movebytes="163427608" reason="compact to meet allocation" />
<expansion type="tenured" amount="54511104" newsize="268435456" timetaken="0.124" reason="insufficient
free space following gc" />
<timesms mark="401.864" sweep="1.628" compact="731.498" total="1135.515" />
<tenured freebytes="90891264" totalbytes="268435456" percent="33" >
<soa freebytes="88207360" totalbytes="265751552" percent="33" />
<loa freebytes="2683904" totalbytes="2683904" percent="100" />
</tenured>
</gc>
<tenured freebytes="78308336" totalbytes="268435456" percent="29" >
<soa freebytes="75624432" totalbytes="265751552" percent="28" />
GC後の容量
<loa freebytes="2683904" totalbytes="2683904" percent="100" />
</tenured>
<refs soft="1654" weak="12117" phantom="87" dynamicSoftReferenceThreshold="9"
maxSoftReferenceThreshold="32" />
<time totalms="1135.678" />
</af>
44
ガーベッジコレクションを実行しても開き領域が確保できない場合、Compactionが発生します。
Compactionはメモリ上に確保されたオブジェクトの位置を動かし参照を変更しなければいけないため、mark
フェーズやsweepフェーズよりも多くの時間を要し、その間アプリケーションは停止させなくてはいけないため、
JVMはできる限りCompactionは行いません。
(GCの実行毎にcompactionが実行されるわけではございません。）
上記はCompactionが発生したときのverbose:gcの出力例になります。Compactionによって移動したオブ
ジェクトの数とサイズ、Compactionの理由、増加された容量を示しています。上記の例では、 4767627個、
計163427608 byteのオブジェクトを移動させた事を示しています。
また、soaとはSmall Object area、loaとはLarge Object areaの略になります。デフォルトでは、64KB以上の
オブジェクトが割り当てられた場合、もしくはsoaにオブジェクトが割り当てられなかった場合にloaにオブジェ
クトが割り当てられます。loaでは、複数スレッドにより同時にオブジェクトを割り当てる事が出来ないのが、注
意点になります。
44
verbose:gcの出力（HeapExpansion）
HeapExpansion発生時
拡張できた容量と最終的な容量、理由
native_stderr.log
<af type="tenured" id="3" timestamp="Mar 31 14:49:20 2009" intervalms="99.201">
<minimum requested_bytes="12582928" />
<time exclusiveaccessms="0.040" meanexclusiveaccessms="0.040" threads="0" lastthreadtid="0x0746B600" />
<refs soft="2013" weak="12117" phantom="87" dynamicSoftReferenceThreshold="9"
maxSoftReferenceThreshold="32" />
<tenured freebytes="35733624" totalbytes="213924352" percent="16" >
<soa freebytes="35733624" totalbytes="213924352" percent="16" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="50" totalid="50" intervalms="99.862">
<compaction movecount="4767627" movebytes="163427608" reason="compact to meet allocation" />
<expansion type="tenured" amount="54511104" newsize="268435456" timetaken="0.124" reason="insufficient
free space following gc" />
<timesms mark="401.864" sweep="1.628" compact="731.498" total="1135.515" />
<tenured freebytes="90891264" totalbytes="268435456" percent="33" >
<soa freebytes="88207360" totalbytes="265751552" percent="33" />
<loa freebytes="2683904" totalbytes="2683904" percent="100" />
</tenured>
</gc>
<tenured freebytes="78308336" totalbytes="268435456" percent="29" >
<soa freebytes="75624432" totalbytes="265751552" percent="28" />
<loa freebytes="2683904" totalbytes="2683904" percent="100" />
</tenured>
<refs soft="1654" weak="12117" phantom="87" dynamicSoftReferenceThreshold="9"
maxSoftReferenceThreshold="32" />
45
<time totalms="1135.678" />
</af>
さらにCompactionでも充分な容量が確保できない場合、ヒープ領域の拡張が行われます。ヒープの拡張
が行われるのは、容量が確保できない場合以外にも、空き領域が最小空き領域として指定した値（デフォル
ト0.3）よりも少なくなった場合、GCの総実行時間がシステム起動からの経過時間の13％を越えた場合に発
生します。
上記は、HeapExpansionが発生したときのverbose:gcの出力例です。GC後に十分な領域を確保することが
出来ず、ヒープの拡張を試みています。最終的に54511104 byteの領域が拡張され、全体として領域が
268435456 byteになったことを示しています。また、JDK5.0より、HeapExpansionの理由が記録されるように
なりました。(例：reason="insufficient free space following gc" )
45
verbose:gcの出力（OutOfMemory）
OutOfMemory発生時
SnapDump、HeapDump、JavaDump
が出力されたことを示す
native_stderr.log
JVMDUMP006I ダンプ・イベント "systhrow"、詳細 "java/lang/OutOfMemoryError" を処理しています - お待ちください。
JVMDUMP007I JVM は Snap ダンプ
('C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥Snap.20090331.145004.2248.0003.trc' を使用する) を要求し
ていますJVMDUMP010I Snap ダンプは
C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥Snap.20090331.145004.2248.0003.trc に書き込まれました
JVMDUMP007I JVM は Java ダンプ
('C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥javacore.20090331.145016.2248.0009.txt' を使用する) を要
求しています
JVMDUMP010I Java ダンプは
C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥javacore.20090331.145016.2248.0009.txt に書き込まれました
JVMDUMP013I ダンプ・イベント "systhrow"、詳細 "java/lang/OutOfMemoryError" を処理しました。
JVMDUMP007I JVM は Heap ダンプ
('C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥heapdump.20090331.145004.2248.0006.phd' を使用する)
を要求しています
JVMDUMP010I Heap ダンプは
C:¥opt¥IBM¥WebSphere¥AppServer¥profiles¥AppSrv01¥heapdump.20090331.145004.2248.0006.phd に書き込まれま
した
verbose:gcからメモリの圧迫の様子がわかる
メモリが圧迫されているときの特徴
¾
¾
GCの発生間隔が短い
1回のGCの開放量が少ない
46
それでも空き領域が確保できないと、やがてメモリ領域を使い果たし、OutOfMemoryとなります。上記は
OutOfMemoryが発生したときのverbose:gcの出力例です。JVMがSnapDumpとHeapDump、JavaDumpの出
力を要求し、指定された位置に出力されたことがわかります。なおOutOfMemory発生時は、SnapDumpも
HeapDump、JavaDumpも自動で出力されるようにデフォルトで設定されています。
また、verbose:gcの出力結果を、メモリリークの有無についての１つの判断材料とすることが可能です。メモ
リが圧迫されると、GCの発生間隔が短くなる、1回のGCの開放量が小さくなる、といった現象が見られます。
verbose:gcを取得するとGCの発生間隔やメモリの開放量が確認できますので、メモリに問題があると思われ
る場合にverbose:gcは非常に有用です。
46
verbose:gc解析ツール － PMAT
GUIベースのverbose:gc解析ツール
以下からフリーで入手可能
以下のコマンドにて起動し、native_stderr.logファイルを選
択する
http://www.alphaworks.ibm.com/tech/pmat
ｊava –jar <PMAT_ROOT>¥ga<version>.jar
ISAを導入していれば、ISAプラグインとしてツールから使
用可能（事前にプラグイン追加しておく必要がある）
47
verbose:gc解析ツールの一つにPMAT （IBM Pattern Modeling and Analysis Tool for java Garbage
Collector）があります。PMATはJavaで書かれたverbose:gc解析用のツールであり、操作はすべてGUIから
実行できるのが特徴です。
PMATは単体で使用する場合、起動は以下のコマンドを実行します。PMAT起動後、native_stderr.logファ
イルを選択して下さい。(<PMAT_ROOT>はPMATをインストールしたディレクトリを指します。)
#java –jar <PMAT_ROOT>¥ga<version>.jar
また、PMATはISAのプラグインとして使用することも可能です。この場合は、事前にISAにPMATをプラグイ
ン追加しておくことで、ISAのツールから起動することができます。
PMATについての詳細は下記URLをご参照ください。
- IBM Pattern Modeling and Analysis Tool for Java Garbage Collector
http://www.alphaworks.ibm.com/tech/pmat
47
PMATを用いたverbose:gc解析
統計情 報
推奨チューニング
グラフ表示も可能
48
PMATを起動してnative_stderr.logを読み込ませると上記のような概要画面が表示されます。ここではGCや
Allocation Falureの発生回数などの概要に加え、Recommendationsには現状で推奨されるチューニング内
容も表示されます。また、「Graph View」を選択することにより、ヒープの使用状況やGCの発生状況など、確
認したい項目をグラフ化することができます。
48
GCトレース
GCトレースを利用することで、GCの挙動を更に詳細に把握
できる
出力される量が膨大で、出力内容の絞込みが必要
設定方法
¾
JVM引数に以下のオプションを指定する
-Xtgc:<オプション名>
例：-Xtgc:backtrace,compaction
ログの出力先
¾
¾
デフォルト：各AppServerのnative_stderr.log
出力場所は変更可能
49
GCトレース(-Xtgc：<オプション名>)とは、verbose:gcよりも更に詳細にガーベッジコレクションの実行状況
をトレースし、native_stderr.logに出力するものです。これを参照することは問題判別のみならずパフォーマ
ンスチューニングにおいても有用です。ただし、膨大な量が出力されるので、出力内容の絞込みが重要で
す。-Xtgcのオプションについては、次ページを参照して下さい。
49
GCトレースのオプション
オプション
内容
サンプル出力
backtrace
GCのトリガーとなったスレッド情報
"main" (0x0003691C)
compaction
compactionに関連する情報
Compact(3): reason = 7 (forced compaction)
Compact(3): Thread 0, setup stage: 8 ms.
Compact(3): Thread 0, move stage: handled 42842 objects in
13 ms, bytes moved 2258028.
concurrent
Concurrent Mark情報
<CONCURRENT GC BK thread 0x0002645F (started after
GC(5)) traced 25435>
dump
Sweepフェーズ情報
<GC(4) 13F9FE44 freelen=x000002C4 -- x00000038
spec/jbb/Stock>
excessiveGC
GCのサイクルの統計情報
excessiveGC:
gcid="10" intimems="122.269" outtimems="1.721"
percent="98.61" averagepercent="37.89"
freelist
前回のGCからのfreelistとallocation
の統計情報
<Alloc TLH: count 3588, size 3107, discard 31>
< non-TLH: count 6219, search 0, size 183, discard 0>
parallel
Parallel Mart、Parallel Sweep情報
Mark: busy stall tail acquire release
0:
30 30 0 0 3
1:
53 7 0 91 94
references
GC中の活動情報
enqueuing ref sun/misc/SoftCache$ValueCell@0x1564b5ac >0x1564b4c8
scavenger
Scavenger GCの情報
{SCAV: | class | instances of age 0-14 in semi-space
terse
GC前後のheapの内容をdump
*DH(1)* 230AD778 a x0000001C java/lang/String
*DH(1)* 230AD794 a x00000048 char[]
50
上記表は、GCトレースのオプションになります。JVMの各サブコンポーネントが出力可能なトレースは、取
得する内容に応じて複数のオプションに分かれています。この中からひとつのオプションを選択してトレース
を出力するだけでも非常に大きなサイズのログが出力されるため、必要なオプションのみを必要な時にだけ
取得するように心がける必要があります。
50
JavaDump (1/3)
Javaプロセスが異常終了したとき、または明示的に命令を
送った時に出力されるテキストベースの診断情報
Javacore、Javaスレッドのダンプファイル、スレッドダンプとも呼ばれ
ている
JVMの状態についての情報を出力したスナップショット
取得できる情報は稼動プラットフォームに依存
¾
ダンプから取得できる情報例：
z
z
z
z
z
z
OS関連情報
環境変数
スレッド情報
native stack
lock情報
memory情報
51
JavaDumpは、ある時点におけるJVMのコンポーネントの状態を示すダンプ情報になります。JavaDumpは
Javacoreとも呼ばれ、WebSphere Application ServerのInformationCenterではJavaスレッドのダンプファイル、
スレッドダンプとも表記されますが、どれも同一のダンプを示しています。JavaDumpはJVMプロセスがクラッ
シュやOutOfMemory等が発生した場合、またはユーザーが外部から明示的に出力命令を送ることで出力さ
れます。JVMプロセスが遮断された場合は、OSが命令を送って出力されます。デフォルトではJavaDumpの
設定はONです。
JavaDumpは、その瞬間にJVMが持っている情報をテキストファイルとして出力します。JavaDumpの出力先
はJVMの作業ディレクトリ（デフォルトは環境変数USER_INSTALL_ROOT）になります。CPU_TIMEは1970年
1月1日からの経過時間を秒単位で示したものになります。また、出力先ディレクトリはプロセス定義の環境エ
ントリーIBM_JAVACOREDIRの設定により変更することも可能です。
51
JavaDump (2/3)
JavaDumpの生成条件
JVMがダウンした場合
¾
OutOfMemoryが発生した場合
¾
デフォルト設定では、ダウンした際に自動的に出力
環境変数IBM_JAVADUMP_OUTOFMEMORY=FALSEにより出力させないこと
も可能
ユーザーがJavaプロセスに対して明示的に命令を発行して生成
¾
ユーザーがOSのコンソールから明示的に命令を送信して取得
¾
WASの管理ツール（wsadmin）により取得
z
kill –QUIT <process id>
wsadmin>set jvm [$AdminControl completeObjectName type=JVM,process=server01,*]
wsadmin>$AdminControl invoke $jvm dumpThreads
wsadmin>jvm = AdminControl.completeObjectName('type=JVM,process=server01,*')
wsadmin>AdminControl.invoke(jvm, 'dumpThreads')
¾
アプリケーションからソースコード上で、出力を指示
z
static com.ibm.jvm.Dump.JavaDump()
52
JavaDumpの生成条件をJVMプロセスのダウンのケースと明示的に出力させるケースとに分けてご説明さ
せて頂きます。
JVMプロセスがダウンした場合やOutOfMemory発生時に、デフォルト設定では自動的にJavaDumpが出力
されます。また、ユーザが意図的にJavaDumpを出力させることも可能です。AIXやLinuxのkillコマンドを用い
て取得したいプロセスIDにkill –QUIT（kill –3 ）のコマンドを送信することにより生成する方法、WASの
wsadminを使用して生成する方法、アプリケーション内でstaticメソッドcom.ibm.jvm.Dump.JavaDump()を呼び
出すことで生成する方法があります。
WASに関連する問題が発生し、ログやトレースの解析では判明できない場合は、WASを再起動される前
にJavaDumpを出力させておくと、今後の解析に役立つ事がございます。
52
JavaDump (3/3)
JavaDump取得のための設定
デフォルトでONのため特に設定は必要ない
OFFに設定することも可能
¾
JavaDumpの出力先
以下の候補を上から順に、存在の有無と書き込み属性をチェックし、
書き込み可能な場所に出力
¾
¾
¾
¾
¾
環境エントリー： DISABLE_JAVADUMP=trueと指定することでOffの設定となる
環境エントリー： IBM_JAVACOREDIR の場所
ＪＶＭプロセスのカレント・ワーキング・ディレクトリ（デフォルトは
USER_INSTALL_ROOT ）
（setされている場合）環境変数： TMPDIR の場所
/tmpディレクトリ、または(Windows環境のみ)環境変数： TEMP の場所
(Windows環境のみ)上記のどの場所も不可能だった場合はSTDERRへ出力
JavaDumpファイル名
[Windows & Linux] javacore.YYYYMMDD.HHMMSS.PID.txt
[AIX]
javacorePID.TIME.txt
53
JavaDumpは、以下の環境エントリーの設定、または実行時のJVM引数の設定によりOFFにすることも可能
ですが、特別な理由がない限りOFFしないで下さい。
環境エントリー：DISABLE_JAVADUMP=true
JVM引数：-Xdisablejavadump
また、出力先ディレクトリは環境エントリーIBM_JAVACOREDIRの設定により変更することも可能です。
JavaDumpのファイル名は以下になります。
(Windows & Linux)javacore.YYYYMMDD.HHMMSS.PID.txt
(AIX)javacorePID.TIME.txt
53
JavaDumpの取得情報
いくつかのサブコンポーネントに分類
TIＴLE subcomponent
GPINFO subcomponent
ENVINFO subcomponent
MEMINFO subcomponent
LOCKS subcomponent
THREADS subcomponent
CLASSES subcomponent
：OS発行のシグナル、日付、ファイル名の情報
：OSレベル、CPUの情報
：Java・VM・JITのバージョン、実行時の引数の情報
：メモリーに関する情報
：LOCKに関する情報
：存在しているスレッドとスタックトレースのリスト
：クラスローダーに関する情報
54
JavaDumpの出力はいくつかのサブコンポーネントに分類されています。そのサブコンポーネントの説明は
上記の通りです。このうち問題判別に特に有効なのはLOCKS(Lockに関する情報)とTHREADS(スレッドのス
タックトレース)のサブコンポーネントになります。次ページ以降にて出力例をご紹介させて頂きます。
54
JavaDumpの出力（再帰呼び出し）
THREADS subcomponentに注目
存在するスレッドとスタックトレースの情報
スタックトレースより、同じメソッドが何度も呼ばれていることがわかる
javacoreYYYYMMDD.HHMMDD.<process id>.txt
0SECTION
THREADS subcomponent dump routine
NULL
=================================
1XMCURTHDINFO Current Thread Details
NULL
---------------------3XMTHREADINFO
"Signal dispatcher" (TID:0x101EB960, sys_thread_t:0x213638A0, state:R, native ID:0x960)
prio=5 NULL
1XMTHDINFO All Thread Details
出力時点での全スレッドの状態を記録
NULL
-----------------NULL
2XMFULLTHDDUMP Full thread dump J9SE VM (J2RE 5.0 IBM J9 2.3 AIX ppc-32 build
20070322_12058_bHdSMR, native threads):
3XMTHREADINFO
"WebContainer : 1" (TID:0x1034AD60, sys_thread_t:0x25847B48, state:CW, native
ID:0x1490) prio=5
Thread.sleepを呼び出した状態
4XESTACKTRACE
at java.lang.Thread.sleep(Native Method)
4XESTACKTRACE
at com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:17)
4XESTACKTRACE
at com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
4XESTACKTRACE
at com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
4XESTACKTRACE
at com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
RecursiveCall.javaの17行目
4XESTACKTRACE
at com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
doRecursiveCallメソッドがsleep
4XESTACKTRACE
at RecursiveCall.javaの18行目
com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
メソッドを呼び出した
4XESTACKTRACE
at doRecursiveCallメソッドが
com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
55
4XESTACKTRACE
at 再度doRecurisiveCallメソッドを呼んでいる
com.ise.waspd.jvm.RecursiveCall.doRecursiveCall(RecursiveCall.java:18)
・・・・・・
（この状態が無限に続き、ループに）
上記例は、同一メソッドによる再帰メソッドが無限に起こり続けている際のJavaDumpの出力例です。
THREAD subcomponent dump routineを参照します。存在するスレッドとスタックトレースの情報が記録さ
れていますので、スレッドのスタックトレースを確認すると、WebContainer:1というスレッドがThread.sleepメ
ソッドを呼び出した状態で停止しており、さらにそのsleepメソッドは
com.ise.waspd.jvm.RecursiveCall.doReCursiveCallメソッドから呼ばれたことがわかります。さらにその後に同
じメソッドが何度も繰り返し呼ばれていることから、このプログラムが再帰処理を続けていることがわかります。
55
JavaDumpの出力（Lock）
LOCKS subcomponentに注目
LOCKに関する情報
Monitor Pool Dump欄により、どのスレッドのオブジェクトがどのスレッドのオ
ブジェクトによってLockされているかが判断できる
javacoreYYYYMMDD.HHMMDD.<process id>.txt
0SECTION
LOCKS subcomponent dump routine
オブジェクトのLockに関する情報を記録
NULL ============================
・・・・・・・
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
2LKMONINUSE
sys_mon_t:0x0028AE90 infl_mon_t: 0x0028A898:
3LKMONOBJECT com.ibm.ws.util.BoundedBuffer@124E1798/124E17A0: <unowned>
3LKNOTIFYQ Waiting to be notified:
“Thread-0”はjava.lang.Object@3030DF38/3030DF40のロック開
3LKWAITNOTIFY "WebContainer : 0" (0x250BA170)
放待ち状態にあり、そのObjectが0x07によってロックされている。
2LKMONINUSE sys_mon_t:0x3020DAE8 infl_mon_t: 0x00000000:
3LKMONOBJECT java.lang.Object@3030DF38/3030DF40: Flat locked by thread ident 0x07, entry count 1
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "Thread-0" (0x353366F0)
・・・・・・・
ID 0x07は”Thread-1”を示している
1LKFLATMONDUMP Thread identifiers (as used in flat monitors):
2LKFLATMON ident 0x07 "Thread-1" (0x35336E90) ee 0x35336C64
2LKFLATMON ident 0x06 "Thread-0" (0x353366F0) ee 0x353364C4
・・・・・・・
56
上記例は、あるスレッドのオブジェクトが他のオブジェクトにLockされている際のJavaDumpの出力例です。
LOCKS subcomponent dump routineを参照します。ここにはオブジェクトのLockに関する情報が記録され
ています。Monitor Pool Dump欄から各スレッドが要求しているオブジェクトと、そのオブジェクトがどのスレッ
ドによって所有されているのかがわかります。どのスレッドによっても所有されていない場合は<unowned>と
記載されますが、所有されている場合はそのスレッドのIDが記載されます。上記例ではスレッドID 0x07に
よってロックされていることがわかります。
さらにThread identifierの欄を見ると、スレッドIDとスレッド名との紐付けを読み取れます。上記例ではID
0x07が「Thread-1」と結び付けられていますので、Thread-0のオブジェクト
java.lang.Object@3030DF38/3030DF40がThread-1のオブジェクトによってロック開放待ちになっていること
がわかります。
56
JavaDumpの出力（Deadlock）
LOCKS subcomponentに注目
LOCKに関する情報
「Deadlock detected!」の内容から、デッドロックの発生箇所が特定できる
javacoreYYYYMMDD.HHMMDD.<process id>.txt
1LKDEADLOCK Deadlock detected !!!
Deadlockに関する情報を記録
NULL
--------------------NULL
2LKDEADLOCKTHR Thread "RightToLeft" (0x886C718)
3LKDEADLOCKWTR is waiting for:
RightToLeftはLeftToRightのス
4LKDEADLOCKMON
sys_mon_t:0x08A49B08 infl_mon_t: 0x0898B128: レッドの保持しているオブジェクト
4LKDEADLOCKOBJ
のロック開放待ち
com.ibm.jp.ws.diagnose.SynchronizedObject@13DE5770/13DE5778:
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "LeftToRight" (0x891C458)
3LKDEADLOCKWTR which is waiting for:
4LKDEADLOCKMON
sys_mon_t:0x063E9BE0 infl_mon_t: 0x00000000:
LeftToRightはRightToLeftのス
4LKDEADLOCKOBJ
レッドの保持しているオブジェクト
com.ibm.jp.ws.diagnose.SynchronizedObject@13DE5728/13DE5730:
のロック開放待ち
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "RightToLeft" (0x886C718)
57
上記例はデッドロックが発生し、DeadLock detectedが検出された際のJavaDumpの出力例です。
片方のオブジェクトがもう一方のオブジェクトのロック開放を待ち、さらにもう一方のオブジェクトが片方のオ
ブジェクトのロック開放を待っている状態がデッドロックです。この状態になると、どちらのスレッドも先に進め
ず、処理がそこで止まってしまいます。この際にJavaDumpを取得すると、LOCKS subcomponentに
「DeadLock detected!」の記述が記録されます。
上でスレッド”RightToLeft“がオブジェクト
com.ibm.jp.ws.diagnose.SynchronizedObject@13DE5770/13DE5778を要求していますが、それがスレッ
ド”LeftToRight“によって保持されていることを示しています。さらに下でスレッド”LeftToRight“がオブジェク
トcom.ibm.jp.ws.diagnose. SynchronizedObject@13DE5728/13DE5730を要求しているが、それがスレッ
ド”RightToLeft“によって保持されていることを示しています。これより、上記例で
は”LeftToRight“と”RightToLeft“がデッドロックの状態に陥っていることがわかります。
このようにして、JavaDumpは現在のスレッドやオブジェクトの状況を知ることができるため、ハングやスローダ
ウン時の原因箇所特定に非常に有用です。
57
JavaDump解析ツール － IBM Thread and Monitor
Dump Analyzer for Java Technology
GUIベースのJavaDump解析ツール
以下からフリーで入手可能
http://www.alphaworks.ibm.com/tech/jca
以下のコマンドにて起動し、javacoreファイルを選択する
ｊava –jar <JCA_ROOT>¥jca<version>.jar
58
JavaDump解析ツールの一つにIBM Thread and Monitor Dump Analyzer for Java Technologyがあります。
IBM Thread and Monitor Dump Analyzer for Java TechnologyはJavaで書かれたJavaDump解析用のツール
であり、操作はすべてGUIから実行できるのが特徴です。
IBM Thread and Monitor Dump Analyzer for Java Technologyの起動は以下のコマンドを実行します。IBM
Thread and Monitor Dump Analyzer for Java Technology起動後、javacoreファイルを選択して下さい。
(<JCA_ROOT>はIBM Thread and Monitor Dump Analyzer for Java Technologyをインストールしたディレクト
リを指します。)
#java –jar <JCA_ROOT>¥jca<version>.jar
IBM Thread and Monitor Dump Analyzer for Java Technologyについての詳細は下記URLをご参照くださ
い。
- IBM Thread and Monitor Dump Analyzer for Java Technology
http://www.alphaworks.ibm.com/tech/jca
58
IBM Thread and Monitor Dump Analyzer for Java
Technologyを用いたJavaDump解析
Thread Detail画面
代表的なスレッドの状態は以下のとおり
・Runnable： 処理を受付可能な状態
・Blocked： 別スレッドが保持しているロッ
クの解放待ち状態
・Waiting on condition： sleep()、wait()メ
ソッドやI/O、join()メソッドによる待ち状態
Monitor Detail画面
リソースのロック解放待ちスレッドの
一覧を表示
59
JVM上のスレッドの状況を確認するには[Analysis] – [Thread Detail]で起動するツールを使用します。この
画面ではRunnable、Blockedなどのスレッドの状態を見やすい形で確認することができます。左画面でスレッ
ドを選択するとそのスレッドのスタックトレースが確認できます。
複数スレッドから要求されているリソースのロック状況を確認するには[Analysis] – [Monitor Detail]で起動
するツールを使用します。上記の赤線内の例ではWebContainer:16が保持しているリソースの解放を6つの
スレッドが待っている状態が確認できます。
59
HeapDump (1/2)
JVMがHeapを使い切ったときに出力
OutOfMemoryが発生
Heap上の全てのオブジェクトの情報を出力
wsadminを用いた手動によるHeapDumpの作成
wsadmin> set obj [$AdminControl queryNames WebSphere:type=JVM,process=server01,*]
wsadmin> $AdminControl invoke $obj generateHeapDump
wsadmin> jvm = AdminControl.queryNames(‘WebSphere:type=JVM,process=server01,*’)
wsadmin> AdminControl.invoke(jvm,’generateHeapDump’)
60
HeapDumpはJVMがヒープを使い果たしたときやクラッシュしたとき、またはユーザーが明示的に命令を
送ったときに生成されます。命令が送られると、その瞬間のヒープ上の全てのオブジェクト情報を出力します。
HeapDumpは、ヒープを使い切ったときにはJavaDumpと同時に出力されます。またV6.0.2から新たに、
wsadminを用いて手動でHeapDumpのみを出力させることも可能になりました。
60
HeapDump (2/2)
ヒープ内に割り当てられているすべての到達可能（live）オブジェクトの
状態を記録
ある時点のヒープの状態を示すスナップショット
¾
HeapDumpによって分かること
¾
¾
アプリケーションのオブジェクトによるヒープの利用状況
ヒープの状態（分断化の度合い、オブジェクトのロード状況）
HeapDumpの出力先
以下の候補を上から順に、存在の有無と書き込み属性をチェックし、書き込
み可能な場所に出力
¾
¾
¾
¾
HeapDump出力前に必ずGCが起動し、到達不可能な“ゴミ”オブジェクトがあまり残らないよ
うな形でデータを出力
環境エントリー： IBM_HEAPDUMPDIR の場所
ＪＶＭプロセスのカレント・ワーキング・ディレクトリ（デフォルトは USER_INSTALL_ROOT ）
（setされている場合）環境変数： TMPDIR の場所
/tmpディレクトリ、(Windows環境 x:¥tmp ここでxはカレントドライブ名)
HeapDumpファイル
Java SDK 1.4.2 SR1より出力フォーマットがphd形式に変更
SR1以降の環境でテキストファイルで出力するには
ファイル名
¾
¾
¾
環境エントリー： IBM_JAVA_HEAPDUMP_TEXT=true の設定が必要
Windows
Linux&AIX
heapdump.YYYYMMDD.HHMMSS.PID.phd
heapdumpPID.TIME.phd
61
JavaDumpがJVMのコンポーネントの状態についての情報を取得するためのデータであるのに対して、
HeapDumpではJVMの仮想ストレージの状態、つまりヒープの中でどのようなオブジェクトがどのように格納さ
れているか、及びどこに空き領域が存在するかなどの状態を表す情報を取得することが出来ます。
JavaDumpにおいてSTコンポーネントについてのダンプを出力することが可能ですが、これはOSから割り当
てているメモリ領域の情報や、GCの方法などのSTコンポーネントそのものの状態についてのダンプ情報で
あるため、HeapDumpの内容とは異なります。
HeapDumpの出力先はJVMの作業ディレクトリ(デフォルトは環境変数USER_INSTALL_ROOT)になり、ファ
イル名はOSによって異なります。また、出力先ディレクトリは環境エントリーIBM_HEAPDUMPDIRの設定によ
り変更することが可能です。
WASV6からHeapDumpの出力ファイルはテキストファイルではなく、PHDファイルになりました。これをテキ
ストファイルで出力させるには、環境エントリーIBM_JAVA_HEAPDUMP_TEXTの設定が必要です。テキスト
形式でHeapDumpを出力するとヒープサイズとほぼ同じ大きさの出力になり、システムのディスクI/Oに大きな
負荷がかかるため、V1.4.2 SR1からはデフォルトの出力フォーマットがテキストからphd形式に変更され、一
回の出力量がテキストのおよそ1/4程度まで小さくなっています。
61
HeapDumpの出力
オブジェクトのアドレス、サイズ、タイプと参照されている
オブジェクトアドレスをリストで表示
HeapDumpの解析には解析ツールが必要
HeapAnalyzer
MDD4J
Heaproots
heapdump.YYYYMMDD.HHMMDD.<process id>.txt
// Version: J2RE 6.0 IBM J9 2.4 Windows XP x86-32 build 20081105_025433_lHdSMr
0x10020000 [32] CLS java/lang/Object
0x10171220
0x10020020 [32] CLS java/lang/J9VMInternals
.......
0x10020780 [56] OBJ [Ljava/lang/String;
0x10021178 0x10021140 0x10021108 0x100210D0 0x10021098 0x10021060
0x10021028 0x10020FF0 0x10020FB8 0x10020F80
1行目：オブジェクトのアドレス、サイズ、タイプ
2行目：参照されている他のオブジェクトのアドレス
62
HeapDumpは、ヒープの構造をシンプルに表現した形式になっています。上記例のように、先頭にJRE情
報があり、オブジェクトの構造を1行目にオブジェクトのアドレス、サイズ、タイプ。2行目に参照されているオ
ブジェクトのアドレス、という形で羅列し、最後にファイルのサマリーが載っている形式になっています。しか
し、このファイルだけを見て解析を行うのは非常に困難ですので、通常はHeapDumpの解析用ツールを用い
て解析を行います。
HeapDumpをメモリリークやOutOfMemoryの発生時に取得し解析ツールにて解析することで、どのオブ
ジェクトがヒープを占領しているのかを見分けることが出来ます。
62
HeapDump解析ツール － HeapAnalyzer
GUIベースのHeapDump解析ツール
以下からフリーで入手可能
http://www.alphaworks.ibm.com/tech/heapanalyzer
以下のコマンドにて起動し、HeapDumpファイルを選択する
ｊava –jar <HA_ROOT>¥ha<version>.jar
63
HeapDump解析ツールの一つにHeapAnalyzerがあります。HeapAnalyzerはJavaで書かれたHeapDump解
析用のツールであり、Javaが動作できる環境であれば、全てのプラットフォームで利用出来ます。操作はす
べてGUIから実行できるのが特徴です。
HeapAnalyzerの起動は、以下のコマンドを実行します。HeapAnalyzer起動後、heapdumpファイルを選択し
て下さい。(<HA_ROOT>はHeapAnalyzerをインストールしたディレクトリを指します。)
#java –jar <HA_ROOT>¥ha<version>.jar
63
HeapAnalyzerを用いたHeapDump解析 (1/2)
状況に応じて、以下の項目を選択し、表示する
ツリー構造
オブジェクトリスト
タイプリスト
ルートリスト
オブジェクト間のサイズのギャップ
ギャップサイズ毎の数
オブジェクト名/タイプ名による検索
アドレスによる検索
64
HeapAnalyzerでは、以下の項目を調査する事が出来ます。問題発生状況に応じて選択して下さい。
・ツリー構造
・オブジェクトリスト
・タイプリスト
・ルートリスト
・オブジェクト間のサイズのギャップ
・ギャップサイズ毎の数
・オブジェクト名/タイプ名による検索
・アドレスによる検索
64
HeapAnalyzerを用いたHeapDump解析 (2/2)
ツリー構造よりリークの疑いがある場所を教えてくれる
Locate a leak suspect
65
HeapAnalyzerの効果的な使用方法として、ツリー構造よりリークの疑いがある場所を教えてくれる機能があ
ります。「Analysis」-「Tree Views」より右クリックにて「Locate a leak suspect」を選択して下さい。
65
JavaDump、HeapDump出力内容の設定（1/2）
汎用JVM引数-Xdump設定
ダンプファイルの種類
ダンプイベントの種類
（設定例）heapdumpの出力回数を3回に変更する場合
名前：汎用JVM引数
値： -Xdump:none -Xdump:heap:events=systhrow,filter=java/lang/OutOfMemoryError,range=1..3
66
JVMのバージョン5.0では、ダンプ機能の実装においてRAS(Reliability, Availability, and Serviceability)機
能が拡充され、新しく-Xdumpオプションが追加されました。
それ以前のバージョンでは、環境変数のJAVA_DUMP_OPTSやIBM_HEAPDUMP_OUTOFMEMORY等でダ
ンプ機能を設定することが可能でしたが、今後は、よりきめ細かい設定が可能である-Xdumpオプションをお
勧め致します。
＜参考＞
・JVM 5.0 SR5未満の環境では、OutOfMemoryError発生時にJavacoreおよびHeapdumpが出力されません
(WAS-08-006)
http://www-06.ibm.com/jp/domino01/mkt/cnpages1.nsf/page/default-0003F586
66
JavaDump、HeapDump出力内容の設定（2/2）
環境エントリーJAVA_DUMP_OPTS
出力するダンプの種類を設定可能
環境変数
JAVA_DUMP_OPT=“ON<condition>(<dumptype>),・・・・・”
condition
ANYSIGNAL, DUMP, ERROR, INTERRUPT, EXCEPTION,OUTOFMEMORY
dumptype
ALL, NONE, JAVADUMP, SYSDUMP, HEAPDUMP
condition: Javacoreファイルの生成条件を指定
¾
¾
¾
¾
dumptype: 生成するダンプの種類
¾
¾
¾
DUMP： CTRL-BREAK(Windows環境)やCTRL-¥（AIX, Linux）によりJavacoreを出力
ERROR： JVMの内部で検知されたエラーによって異常終了
INTERRUPT： CTRL-CなどによりJavacoreを出力
OUTOFMEOMRY： OutOfMemory（メモリ不足）エラーが発生
SYSDUMP： OSが生成するコアファイル
HEAPDUMP： ヒープダンプ
JAVADUMP： JavaDumpファイル
推奨値
¾
JAVA_DUMP_OPTS="ONERROR(JAVADUMP,SYSDUMP)
ONEXCEPTION(JAVADUMP,SYSDUMP), ONDUMP(JAVADUMP)"
67
前ページで、ダンプの設定を行う際は-Xdumpを使用することをお勧めしておりますが、これまで同様に環
境エントリーJAVA_DUMP_OPTSを使用して引き続き設定することも可能です。この環境変数を使用すること
で、どのような状況で (どのような命令が送られたときに) 、どの種類のダンプを生成するか設定することが可
能です。
生成条件のDUMP,ERROR,INTERRUPTの各レベルに対してどの信号がマッピングされているかはプラッ
トフォームによって異なっており、詳細はdiagnostic guideに掲載されています。問題判別を行うときには、一
般に各OSが生成するCoredumpファイルも有用な情報を提供する場合が多いため、設定を以下のように変
更することが望ましいとされています。
・Diagnostic Guide, Chapter 25 Using Heapdump(p.370)
JAVA_DUMP_OPTS="ONERROR(JAVADUMP,SYSDUMP) ONEXCEPTION(JAVADUMP,SYSDUMP),
ONDUMP(JAVADUMP)"
67
その他JavaDump、HeapDumpに関する環境エントリー
管理コンソールにて設定
アプリケーションサーバー選択後、 「Javaおよびプロセス管理」から「プロセ
ス定義」→「環境エントリー」 にて設定
環境変数名
値
Memo
IBM_HEAPDUMP 又は
IBM_HEAP_DUMP
true/false
Heap Dumpの機能を有効にする
IBM_HEAPDUMP_OUTOFMEMORY
true/false
IBM_JAVACOREDIR
fullpath
OutOfMemoryをhookし、Heap Dumpを生成する
機能を有効にする
JavaDumpの出力先変更
IBM_HEAPDUMPDIR
fullpath
HeapDumpの出力先変更
IBM_JAVA_HEAPDUMP_TEXT
true/false
IBM_JAVA_HEAPDUMP_TEST
true/false
TMPDIR
fullpath
PHDフォーマットかTXTフォーマットかを選択す
る
PHD＋TXTフォーマットの二種類のHeap Dump
を同時に生成する
Heap Dumpの出力先が利用不能な場合に書き
出し先となるディレクトリ
68
上記の表は、JavaDumpとHeapDumpに関する環境エントリーの一覧になります。これらの環境変数は管理
コンソールからアプリケーションサーバーを選択し、「Javaおよびプロセス管理]から「プロセス定義」→「環境
エントリー」の画面から設定可能です。デフォルトでは何も表記されていませんので、手動で変数と値を設
定する必要があります。出力先やファイル名を変更したいときは参考にして下さい。
68
クラス・ローダー・ビューワー
クラス･ローダー・ビューワー
クラス･ローダーの階層構造や各クラス･ローダー毎のクラスパス、各クラス･ロー
ダーがロードしたクラスを確認可能
管理コンソールに組み込まれたWASの基本機能
クラス･ローダーがロードしたクラスを確認するためには、事前にアプリケーショ
ン･サーバーでクラス・ローダー・ビューアー・サービスを有効にする必要あり
クラス･ローダーはディスク上のクラスファイルを
メモリー上にロードする
クラス･ローダーは対象クラス･パスごとに複数存在
メモリー
クラス･ローダーの階層構造を表示
クラス･パス等の情報のファイル保存も可能
Javaクラス･ローダー
Class Hello
WebSphere拡張クラス･ローダー
ディスク
アプリケーション･クラス･ローダー
Hello.class
WARクラス･ローダー
69
クラスローダーに関連する問題が発生した際に、非常に有用となるツール・設定を紹介させて頂きます。
クラスローダーの階層構造や各クラスローダ毎のクラスパス、特定のクラスローダーによってロードされたクラ
ス等を確認して下さい。
①クラス・ローダー・ビューワー
管理コンソールより「トラブルシューティング」-「クラス・ローダー・ビューワー」を選択して下さい。
69
クラス・ローダー設定
クラス・ローダーのトレース設定
com.ibm.ws.classloader.*=all
[09/04/11 18:20:44:428 JST] 0000001d ClassGraph 3 application class loader:
com.ibm.ws.classloader.JarClassLoader@43e243e2
com.ibm.ws.classloader.CompoundClassLoader@190c190c[app:Provider2]
Local ClassPath:
Parent: com.ibm.ws.classloader.ProtectionClassLoader@51545154
Delegation Mode: PARENT_FIRST
trace.log
クラス・ローダーに関連するJVM引数
-verbose：class
¾
¾
¾
native_stderr.log
管理コンソールの冗長クラス・ロードと同一の設定
クラスローダーが検索したクラスパスの階層構造を表示
特定のクラスのみ表示させる場合は、-Dibm.cl.verbose=myPackage.myClass
class load: com.ibm.ws.security.config.AuditKeystoreConfig from:
file:/opt/IBM/WebSphere/AppServer/plugins/com.ibm.ws.runtime.jar
class load: com.ibm.ws.security.policy.DynamicPolicyFactory from:
file:/opt/IBM/WebSphere/AppServer/plugins/com.ibm.ws.runtime.jar
-verbose：dynload
¾
¾
¾
native_stderr.log
クラス名とパッケージ名を表示
クラスのサイズとクラスのロードに要した時間を表示
Jarファイル名をフルパスで表示
<Loaded com/ibm/ws/management/discovery/transport/MBeanDiscoveryHelper$ConnectorInfo>
70
< Class size 960; ROM size 528; debug size 0>
< Read time 5 usec; Load time 68 usec; Translate time 191 usec>
②クラス・ローダーのトレース設定
管理コンソールより「トラブルシューティング」-「ログおよびトレース」-「ログ詳細レベルの変更」を選択して下
さい。
③クラス・ローダーに関連するJVM引数
・-verbose:class
管理コンソールより、「サーバー」-「アプリケーションサーバー」-「Javaおよびプロセス管理」-「プロセス定
義」-「Java 仮想マシン」にて「冗長クラス・ロード」をONにして下さい。もしくは、汎用JVM引数に、verbose:classと入力して下さい。また、特定のクラスのみを表示させたい場合には、-Dibm.cl.verboseにて指
定して下さい。
・-verbose:dynaload
管理コンソールより、「サーバー」-「アプリケーションサーバー」-「Javaおよびプロセス管理」-「プロセス定
義」-「Java 仮想マシン」にて「汎用JVM引数」に、-verbose:classと入力して下さい。
70
２.問題判別
２－１ ログ、トレース
２－２ JVM問題判別
２－３ 症状別問題判別
71
71
ブラウザへ応答が返ってこないときの問題判別の一例
•F/Wや負荷分散装置がある場合、そこに対する調査も行う。
No
Pingは通るか
ネットワークの問題判別
Yes
Webサーバーは起動しているか（プロセスのチェック）
Yes
No
Webサーバーダウン?
ログ/設定coreの確認
No
Webサーバー上のコンテンツへのリクエストは返ってくるか
Yes
No
アプリケーションサーバーは起動しているか（プロセスのチェック）
Yes
Javaプロセスダウン?
ログ/JavaDumpのチェック
WASやアプリケーションのログの確認、解析
特に何も出ていない
No
Webサーバーを経由せず、HTTPトランスポートから
アプリケーションサーバーへ直接アクセスした場合も応答無し
Plug-inが怪しい
ログの確認
Fixの有無の確認
トレース取得
Yes
CPU使用率の調査
高負荷
リソースの限界の可能性?
ループ?→JavaDumpの取得/解析
CPUを使っているの アプリケーション
はどのプロセスか？ サーバープロセス
ほとんど使っていない
他のアプリケーションへは、応答が正常に返ってくるか
No
他のプロセス そのプロセスの調査
（バッチなどが重い?）
Yes
問題のアプリケーション内でのトレースの取得・解析（どこで止まるのか）
ハング? 再現性の確認
アプリケーションの見直し
JavaDumpの取得/解析
72
上記はブラウザから応答が返ってこないときの問題判別手順の一例を示したものになります。
Pingは正常に通るか、Webサーバーは起動しているか、静的コンテンツへのリクエストは返ってくるか、など
一つ一つの問題を切り分けて問題判別を行います。また負荷分散装置やファイアウォールなどがある場合
は、それに対する調査も必要になります。
72
ハング/ループ
プロセスは存在しているが、応答が無い
リソースの処理待ちであったり、パフォーマンス劣化によるスローダウ
ン状態ではない
主な原因
アプリケーションや製品の問題
¾
¾
デッドロック
再帰呼び出しによる無限ループ
対応：JavaDumpの取得が有効
ハードウェアやWASのリソースを使い切っていないかを確認
十分なリソースがあるにもかかわらず問題が発生している場合
JavaDumpの取得し、デッドロックや無限ループの存在を確認する
73
ハングは、プロセスは存在しているにもかかわらず応答がない現象になります。
主な原因としては、アプリケーションまたは製品のバグに起因する場合があります。スレッドがデッドロック
を起こし停止してしまう場合や、再起呼び出しによる無限ループが発生し、結果的に応答がなくなる場合が
あり、最終的にStackOverflowでJVMがダウンしてしまう可能性もあります。ハングが発生した際、CPU使用率
があまり高くない場合にはデッドロック、CPU使用率が高い場合には再起呼び出しによる無限ループの状
態になっていることが考えられます。この場合は、JavaDumpの取得が有用です。 （→「JavaDump」）
また、後方リソースの処理待ちに起因する場合もあります。この場合、DBやMQなど、後方リソース処理や
ネットワーク処理などにより、スレッドがI/O処理待ちの状態となります。この場合、後方のリソースについて
問題判別を行う必要があります。
また、パフォーマンスの劣化により、レスポンスが返ってこないように感じられる場合です。この場合、遅く
てもレスポンスが帰ってくる状態であれば、後方リソースまたはパフォーマンスの問題と考えられます。(次
ページ「スローダウン」参照)
73
スローダウン
レスポンスが遅い
ハング/ループではなく、やがてはレスポンスが返ってくる状態
主な原因
マシンのリソースの限界：CPU使用率やDISK I/Oなどの調査
¾
¾
情報収集や、その他のアプリケーション（バッチなど）
¾
¾
事前に負荷テスト・パフォーマンスチューニングを行い、リクエストをどこまで受付
可能か、限界値を見極めておく
負荷分散装置などでそれ以上のリクエストがこないように流量制限
トレースがONになっていたり、情報収集自体の負荷はないか
grep/find/tailなどのコマンドもシステムに負荷を与えることがあるので注意
対応：ボトルネックの特定が必要
OS、ネットワーク、ソフトウェアなど、全体を見て検出
Webサーバーでレスポンスタイム記録 ＋ 要求メトリックが有用
（→ 「IHSアクセスログのカスタマイズ」）
74
スローダウンは、個々の構成要素は正常に稼動しているにも関わらず、レスポンスが返ってくるのが非常
に遅い現象になります。
主な原因は、マシンのリソースの限界や他のアプリケーションの影響が考えられます。マシンのリソースは
CPU使用率などを調査し、必要以上に負荷がかかっていないかを確認します。その場合には、負荷分散装
置などを利用し、それ以上のリクエストがこないように流量制限することも考慮にいれなくてはなりません。ま
た、事前に負荷テストやパフォーマンスチューニングを行い、リクエストをどこまで受付可能か、限界値を見
極めておくことも重要になります。
また、他のアプリケーションやバッチの影響もあります。見落としがちですが、grepやfind、tailなどのコマン
ドもシステムに負荷を与えることがあるので注意が必要です。
スローダウンを解決するには、そのボトルネックがどこにあるのかを検出することが非常に重要です。考え
られるボトルネックとしては、OSレベル、Network、ソフトウェアなどシステム全体からそのボトルネックを検出
することが重要です。OSレベルであればvmstatコマンド、ソフトウェアであれば、 Webサーバーでレスポンス
タイム記録を取得し、要求メトリックを利用してコンポーネントごとのレスポンスタイムを取得することが有用で
す。(→「IHSアクセスログのカスタマイズ」)
74
OutOfMemory
メモリ領域を使い切った状態
主な原因
Java heap領域の不足
Native heap領域の不足
対応：GCやメモリ領域のチェック
verbose:gc
¾
¾
出来る限り、通常時から取得して下さい
より詳細なGCの挙動を確認したい場合には、GCトレースを取得して下さい
HeapDumpの解析
¾
¾
正常時に1回取得しておくと、障害発生時の分析に便利である
再現可能な状況で、PDを行う際には、問題発生までの時間の経過に合わせて
（もしくは、状況に応じて）2回程取得することを推奨
75
OutOfMemoryは、メモリー領域を使い切ってしまい、ログにOutOfMemoryエラーが出力されJVMがダウン
する現象になります。
主な原因としては、Java heap領域の不足の場合とNative heap領域の不足の場合があります。
OutOfMemoryが発生した時には、GCがどのように行われ、メモリ領域がどのように使われているのかチェッ
クする必要があります。そのために取得すべき情報としては、 verbose:gc、HeapDumpがあります。（→
「verbose:gc」）また、より詳細なGCの挙動を確認したい場合には、GCトレースを取得して下さい。
(→Hits&Tips「GCトレース」)
正常時の状況のHeapDumpを事前に取得しておき、問題発生時に比較することにより、問題判別がよりス
ムーズに進みますので、正常時に一度HeapDumpを取得しておくことをお勧め致します。また、問題判別を
行う場合には、問題発生までの時間の経過に合わせて２回程度Heapdumpを取得することを推奨します。ま
た、AIXであれば、svmonコマンドによりメモリー使用量の変化を追うことも有効です。
75
クラッシュ
JVMの異常終了
主な原因
Native Code（JNI）の問題
JVMそのものの問題
サポートセンターに依頼
クラッシュ時はCore、JavaDumpは自動で出力
76
クラッシュは、SIGSEGV (incorrect access to memory) 、SIGILL (illegal instruction) などでJVMが異常終
了する現象になります。
主な原因としては、Native Code (JNI)の問題やJVMそのものの問題が考えられます。JNIの問題としては、
JDBCドライバーの問題なども含まれます。
この場合には、CoreやJavaDumpが自動で取得されます。その原因がJVMの問題と考えられる場合には、
CoreとJavaDumpファイルを取得し、IBMサポートセンターに報告します。通常、クラッシュの場合、IBMサ
ポートセンターに問題を解析してもらうことになりますが、JavaDumpを参照することによって、現場のSEがそ
の問題判別をできる場合もございます。
76
まとめ・参考文献
77
77
まとめ
問題判別の心得
基本手順、確認すべきサイト、情報収集方法について確認しました。
問題判別
以下の項目に分類し、問題判別方法について確認しました。
¾
各コンポーネントのログ・トレース
¾
JVM問題判別方法
¾
症状別問題判別方法
z
z
z
Edge Component、IHS、プラグイン、WASのそれぞれのログと、トレース取得方法
verbose:gc、JavaDump、Heapdumpの説明と、それぞれの解析ツールとその使用例
ブラウザへ応答が返ってこないときの問題判別の一例、ハング/ループ、スローダウン、
OutOfMemory、クラッシュなど、代表的な症状における問題判別方法
78
78
参考文献
Information Center
WAS V7.0 InformationCenter
¾
WAS V7.0 InformationCenter Webサービス
¾
http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/index.jsp?topic=/com.ibm
.websphere.nd.doc/info/ae/ae/welc6tech_wbs.html
SIL資料
WebSphere Application Server V7.0 管理ガイド
¾
http://publib.boulder.ibm.com/infocenter/wasinfo/v7r0/index.jsp
http://w306.ibm.com/jp/domino02/ise/ISEINFO.NSF/604755fe61c93ffc492563fd002551ec
/6da6bd991b73146a492574fa000e0580?OpenDocument
Guide
Diagnostics Guide
¾
http://www.ibm.com/developerworks/java/jdk/diagnosis/
79
79