javacore読み方


※上記の広告は60日以上更新のないWIKIに表示されています。更新することで広告が下部へ移動します。

最終更新日 2010年05月26日 (水) 20時03分58秒

目標

ここでは、WAS v7環境のjavacoreを読むときのポイントを紹介します。7つのセクションに分かれています。前ページで取得したjavacoreの各セクションを確認してみましょう。

目次

  1. javacoreのTITLEセクション
  2. javacoreのGPINFOセクション
  3. javacoreのENVINFOセクション
  4. javacoreのMEMINFOセクション
  5. javacoreのLOCKSセクション
  6. javacoreのTHREADSセクション
  7. javacoreのCLASSESセクション
  8. まとめ


このセクションでは、Javacoreを取得することで何が分かるのか解説します。
Javacoreの理解を深め、様々な問題ケースにおいて、Javacoreの取得が適切かどうかを判断することが出来るようになりましょう。

Javacore(スレッド・ダンプ、Javadumpともいう)は、Javaのプロセスの断面を見るための有用な診断ツールです。Javacoreにどのような情報が含まれているか見ていきましょう。
※このセクションでは、IBM Java6.0をベースに解説しています。他のJavaのバージョン(1.4.2や5.0等)と出力のされ方が若干異なることがありますが、大体同じです。

Javacoreの情報は"Java Diagnostics Guide"に記載がありますので、もっと深く知りたい方は、是非ご覧ください。
Java Diagnostics Guide 6 - Interpreting a Javadump
http://publib.boulder.ibm.com/infocenter/javasdk/v6r0/index.jsp?topic=/com.ibm.java.doc.diagnostics.60/diag/tools/javadump_interpret.html

Javacoreは大きく8つのセクションに分かれております。 "0SECTION"の間が1つのセクションです。

添付のjavacoreファイルを見ながら読んでいただけると、イメージがしやすいと思います。

1. javacoreのTITLEセクション


このセクションで分かることは、Javacoreが
  • 何故出力されたか (トリガー)
  • いつ出力されたか (日時)
  • どこに出力されたか (場所)
等です。

例えば、
1TISIGINFO     Dump Event "user" (00004000) received 
 
であれば、これはユーザーが意図的に出力したことを示しています。
また、日時やファイル名から連続的に複数のJavacoreが出力されたのか、複数出てはいるが、異なるプロセスに対して出力されたものなのかが分かります。

このTITLEかだけでも、Javacoreを出すようなイベントが、どのぐらいの頻度で発生しているのかを知ることが出来ますね!

2. javacoreのGPINFOセクション


このセクションで分かることは、Javaが動いていた
  • OS情報
  • CPU情報
  • シグナル情報 (SIGSEGV, SIGILL または SIGFPE)
  • ネイティブ・コードの情報 (何のネイティブ・モジュールのどの場所を実行していたときに、Javacoreが生成されたか)
等です。

クラッシュしたとき等はネイティブ・コードの情報が有効だったりします。
明らかに他ベンダーのネイティブ・モジュールの場合にはWASがクラッシュしたからWebSphereサポートに問い合わせるより、
他ベンダーに問い合わせることが判断できれば、初動調査が迅速に行えますね。


3. javacoreのENVINFOセクション


このセクションで分かることは、
  • Javaのバージョン
  • システム・クラスパス情報
  • JVM引数
  • User Limit情報(unix系OSのulimit情報)
  • 環境変数
等です。

Javaのバージョンは結構重要です。WASの累積修正(FixPack)は当ててるけど、ベースのJavaにはまったく当ててないなんていうケースが多いです。
例えば、
1CIJAVAVERSION J2RE 6.0 IBM J9 2.4 Windows XP x86-32 build jvmwi3260-20081105_25433
 
だと、2008年11月のJavaを使ってます。安定稼動のためにも定期的な修正の適用を検討した方が良いと思います。
あまりに古いと、多くの既知障害の影響、複合要因などが考えられるため、原因特定にいたることが出来ないケースもあります。

環境変数やJVM引数が正しく設定された上でJavaが稼動しているかもJavacoreから分かりますね!


4. javacoreのMEMINFOセクション

このセクションで分かることは、

  • Javaヒープの空き容量
  • Javaヒープの合計量(その時点でのJavaヒープの領域)
  • Javacoreが取得された時点から少しさかのぼったGC(ガーベッジ・コレクション)の履歴

等です。Javaヒープの使用推移を把握するには、冗長ガーベッジ・コレクション・ログを用いるのが良いですが、Javacoreからでも
取得時点でJavaヒープのサイズや、そのうちどの程度使用されていたのか等の情報を知ることが出来ます。

0SECTION       MEMINFO subcomponent dump routine
NULL           =================================
1STHEAPFREE    Bytes of Heap Space Free: 544C608 
1STHEAPALLOC   Bytes of Heap Space Allocated: 9888E00 
 
1STGCHTYPE     GC History  
3STHSTTYPE     10:52:10:944968985 GMT j9mm.134 -   Allocation failure end: newspace=0/0 oldspace=105040048/159944192 loa=3834224/4797952 
3STHSTTYPE     10:52:10:944964794 GMT j9mm.139 -   Reference count end: weak=1448 soft=6822 phantom=54 threshold=21 maxThreshold=32 
 

5. javacoreのLOCKSセクション

このセクションで分かることは、

  • JVM内部のロック情報
  • デッドロックの有無

等です。ハングやパフォーマンスの問題ではこのセクションは要チェックです。
Javaスレッドのデッドロックが発生しているときは「Deadlock detected !!!」と出てくれます。

Deadlock detected !!!
---------------------
  Thread "DeadLockThread 1" (0x41DAB100)
    is waiting for:
      sys_mon_t:0x00039B98 infl_mon_t: 0x00039BD8:
      java/lang/Integer@004B2290/004B229C: 
    which is owned by:
  Thread "DeadLockThread 0" (0x41DAAD00)
    which is waiting for:
      sys_mon_t:0x00039B40 infl_mon_t: 0x00039B80:
      java/lang/Integer@004B22A0/004B22AC: 
    which is owned by:
  Thread "DeadLockThread 1" (0x41DAB100)
 
 

デットロックではなくても、たくさんのスレッドが待っているロックがあれば怪しいです。
対象のロックやロックを持つJavaスレッド(下の例では"WebContainer : 0")の処理を確認しましょう。
スレッドの処理の確認は次のTHREADSセクションを見ます。

2LKMONINUSE      sys_mon_t:0x0724F188 infl_mon_t: 0x0724F1C0:
3LKMONOBJECT       com/xxx/xxx/SyncronizedLock@112D5620/112D562C: "WebContainer : 0"
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "WebContainer : 1" (0x056CD200)
3LKWAITNOTIFY            "WebContainer : 2" (0x0574E200)
3LKWAITNOTIFY            "WebContainer : 3" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 4" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 5" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 6" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 7" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 8" (0x05785D00)
3LKWAITNOTIFY            "WebContainer : 9" (0x05785D00)
 
 

6. javacoreのTHREADSセクション


このセクションで分かることは、

  • 全Javaスレッド名とスレッドID
  • Javaスレッドのスタック
  • Nativeスレッドのスタック (Java 6 SR7以降)

等です。javacoreで一番役に立つのがこのセクションです。javacoreを取得した瞬間の全Javaスレッドのスタック情報がダンプされます。
クラッシュ、ハング、Out Of Memoryエラーのどの場合でもjavacoreのTHREADSセクションは確認しましょう。
IBMJava 6 SR7からはそれまでのJavaスタックに加えてNativeスタックもjavacoreに記録されるようになりました。
スレッドの一番上が現在実行中のメソッドです。

3XMTHREADINFO      "SoapConnectorThreadPool : 0" J9VMThread:0x19BFD100, j9thread_t:0x1D6B3A54, java/lang/Thread:0x0317CF48, state:R, prio=5
3XMTHREADINFO1            (native thread ID:0x930, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/jvm/Dump.JavaDumpImpl(Native Method)
4XESTACKTRACE                at com/ibm/jvm/Dump.JavaDump(Dump.java:20)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:600(Compiled Code))
4XESTACKTRACE                at com/ibm/ws/process/Win32ProcessImpl.generateJVMDump(Win32ProcessImpl.java:744)
4XESTACKTRACE                at com/ibm/ws/management/component/JVMMBean.dumpThreads(JVMMBean.java:202)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:600(Compiled Code))
4XESTACKTRACE                at sun/reflect/misc/Trampoline.invoke(MethodUtil.java:37)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:600(Compiled Code))
4XESTACKTRACE                at sun/reflect/misc/MethodUtil.invoke(MethodUtil.java:244)
4XESTACKTRACE                at javax/management/modelmbean/RequiredModelMBean.invokeMethod(RequiredModelMBean.java:1086)
4XESTACKTRACE                at javax/management/modelmbean/RequiredModelMBean.invoke(RequiredModelMBean.java:967)
4XESTACKTRACE                at com/sun/jmx/interceptor/DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:848)
4XESTACKTRACE                at com/sun/jmx/mbeanserver/JmxMBeanServer.invoke(JmxMBeanServer.java:773)
4XESTACKTRACE                at com/ibm/ws/management/AdminServiceImpl$1.run(AdminServiceImpl.java:1320)
4XESTACKTRACE                at com/ibm/ws/security/util/AccessController.doPrivileged(AccessController.java:118(Compiled Code))
4XESTACKTRACE                at com/ibm/ws/management/AdminServiceImpl.invoke(AdminServiceImpl.java:1213)
4XESTACKTRACE                at com/ibm/ws/management/connector/AdminServiceDelegator.invoke(AdminServiceDelegator.java:181)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:600(Compiled Code))
4XESTACKTRACE                at com/ibm/ws/management/connector/soap/SOAPConnector.invoke(SOAPConnector.java:406)
4XESTACKTRACE                at com/ibm/ws/management/connector/soap/SOAPConnector.service(SOAPConnector.java:241)
4XESTACKTRACE                at com/ibm/ws/management/connector/soap/SOAPConnection.handleRequest(SOAPConnection.java:65)
4XESTACKTRACE                at com/ibm/ws/http/HttpConnection.readAndHandleRequest(HttpConnection.java:733)
4XESTACKTRACE                at com/ibm/ws/http/HttpConnection.run(HttpConnection.java:522)
4XESTACKTRACE                at com/ibm/ws/util/ThreadPool$Worker.run(ThreadPool.java:1550)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               setup_native_thread+0x18a (j9introspect.c:333, 0x7FEC3BDA [J9PRT24+0x3bda])
4XENATIVESTACK               j9introspect_threads_nextDo+0xa5 (j9introspect.c:569, 0x7FEC3FF5 [J9PRT24+0x3ff5])
4XENATIVESTACK               protectedNextDo+0x12 (javadump.cpp:3465, 0x7FD19B12 [j9dmp24+0x9b12])
4XENATIVESTACK               j9sig_protect+0x41 (j9signal.c:144, 0x7FECBFA1 [J9PRT24+0xbfa1])
4XENATIVESTACK               JavaCoreDumpWriter::writeThreadSection+0x447 (javadump.cpp:1374, 0x7FD1C087 [j9dmp24+0xc087])
4XENATIVESTACK               protectedWriteSection+0x9 (javadump.cpp:3418, 0x7FD19AB9 [j9dmp24+0x9ab9])
4XENATIVESTACK               j9sig_protect+0x41 (j9signal.c:144, 0x7FECBFA1 [J9PRT24+0xbfa1])
4XENATIVESTACK               JavaCoreDumpWriter::JavaCoreDumpWriter+0x21a (javadump.cpp:318, 0x7FD1C6BA [j9dmp24+0xc6ba])
4XENATIVESTACK               runJavadump+0x1b (javadump.cpp:3514, 0x7FD1C8BB [j9dmp24+0xc8bb])
4XENATIVESTACK               doJavaDump+0x33 (dmpagent.c:823, 0x7FD119E3 [j9dmp24+0x19e3])
4XENATIVESTACK               protectedDumpFunction+0x12 (dmpagent.c:2592, 0x7FD12DA2 [j9dmp24+0x2da2])
4XENATIVESTACK               j9sig_protect+0x41 (j9signal.c:144, 0x7FECBFA1 [J9PRT24+0xbfa1])
4XENATIVESTACK               runDumpFunction+0x5e (dmpagent.c:2569, 0x7FD13B7E [j9dmp24+0x3b7e])
4XENATIVESTACK               runDumpAgent+0x1f0 (dmpagent.c:2495, 0x7FD14270 [j9dmp24+0x4270])
4XENATIVESTACK               createAndRunOneOffDumpAgent+0x97 (dmpagent.c:2412, 0x7FD144A7 [j9dmp24+0x44a7])
4XENATIVESTACK               triggerOneOffDump+0x98 (trigger.c:760, 0x7FD1D3E8 [j9dmp24+0xd3e8])
4XENATIVESTACK               Java_com_ibm_jvm_Dump_JavaDumpImpl+0x1b (dump.c:60, 0x7FC6627B [jclscar_24+0x627b])
4XENATIVESTACK               VMprJavaSendNative+0x421 (jnisend.asm:432, 0x7FF0B181 [j9vm24+0x1b181])
4XENATIVESTACK               JVM_InvokeMethod+0x50 (jvm.c:3969, 0x7FBD4560 [jvm+0x4560])
4XENATIVESTACK               Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 (nativeaccessors.c:28, 0x7F3F663E [java+0x663e])
4XENATIVESTACK               MM_MemoryPoolAddressOrderedList::allocate+0x2dd (memorypooladdressorderedlist.cpp:494, 0x7FE9C14D [j9gc24+0x3c14d])
4XENATIVESTACK               NtQueryPerformanceCounter+0xc (0x7C94D8BA [ntdll+0xd8ba])
4XENATIVESTACK               j9time_hires_clock+0xd (j9time.c:164, 0x7FED472D [J9PRT24+0x1472d])
4XENATIVESTACK               twGetSequenceCounter+0x13 (tracewrappers.c:181, 0x7FD91173 [j9trc24+0x1173])
4XENATIVESTACK               traceV+0x130 (ut_trace.c:1529, 0x7FCBEE70 [j9ute24+0xee70])
4XENATIVESTACK               JVM_InvokeMethod+0x50 (jvm.c:3969, 0x7FBD4560 [jvm+0x4560])
4XENATIVESTACK               MM_TLHAllocationInterface::allocateTLH+0x89 (tlhallocationinterface.cpp:417, 0x7FEA4829 [j9gc24+0x44829])
4XENATIVESTACK               JVM_InvokeMethod+0x50 (jvm.c:3969, 0x7FBD4560 [jvm+0x4560])
4XENATIVESTACK               Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 (nativeaccessors.c:28, 0x7F3F663E [java+0x663e])
4XENATIVESTACK               TR_CompilationInfo::compileMethod+0x2f1 (compilationthread.cpp:2969, 0x7F82A8B1 [j9jit24+0xa8b1])
4XENATIVESTACK               JVM_InvokeMethod+0x50 (jvm.c:3969, 0x7FBD4560 [jvm+0x4560])
4XENATIVESTACK               setTagSumCheck+0x10 (j9memtag.c:60, 0x7FEC4250 [J9PRT24+0x4250])
4XENATIVESTACK               J9HookDispatch+0x8a (hookable.c:175, 0x7FE210BA [J9HOOKABLE24+0x10ba])
4XENATIVESTACK               j9sig_protect+0x41 (j9signal.c:144, 0x7FECBFA1 [J9PRT24+0xbfa1])
4XENATIVESTACK               (0x000A9718)
4XENATIVESTACK               (0x0472FCD8)
4XENATIVESTACK               (0x04748DE8)
 


7. javacoreのCLASSESセクション


このセクションで分かることは、

  • クラスローダーの情報
  • ロードされたクラスの情報

等です。クラスローダー関連の問題(NoClassDefFoundErrorなど)が発生したときはここを確認します。ロードされたクラスのリストを見れば、ある特定なクラスをロードしたのはどのクラスローダーか、を知ることができます。もしそのクラスが見つからなければ、システム中に存在するどのクラスローダーもそのクラスをロードしなかったことになります。

クラス・ローディング問題の神秘を解く 第1回: クラス・ローディングとデバッグ・ツール
http://www.ibm.com/developerworks/jp/java/library/j-dclp1/

0SECTION       CLASSES subcomponent dump routine
NULL           =================================
1CLTEXTCLLOS   	Classloader summaries
1CLTEXTCLLSS   		12345678: 1=primordial,2=extension,3=shareable,4=middleware,5=system,6=trusted,7=application,8=delegating
2CLTEXTCLLOADER		p---st-- Loader *System*(0x100BFE98)
3CLNMBRLOADEDLIB		Number of loaded libraries 5
3CLNMBRLOADEDCL			Number of loaded classes 450
2CLTEXTCLLOADER		-x--st-- Loader sun/misc/Launcher$ExtClassLoader(0x100C3550), Parent *none*(0x00000000)
3CLNMBRLOADEDLIB		Number of loaded libraries 0
3CLNMBRLOADEDCL			Number of loaded classes 0
2CLTEXTCLLOADER		-----ta- Loader sun/misc/Launcher$AppClassLoader(0x100D53D8), Parent sun/misc/Launcher$ExtClassLoader(0x100C3550)
3CLNMBRLOADEDLIB		Number of loaded libraries 0
3CLNMBRLOADEDCL			Number of loaded classes 1
1CLTEXTCLLIB   	ClassLoader loaded libraries
2CLTEXTCLLIB  		Loader *System*(0x100BFE98)
3CLTEXTLIB   			E:\work\SDK\60\SR7\jre\bin\java
3CLTEXTLIB   			E:\work\SDK\60\SR7\jre\bin\jclscar_24
3CLTEXTLIB   			E:\work\SDK\60\SR7\jre\bin\zip
3CLTEXTLIB   			E:\work\SDK\60\SR7\jre\bin\net
3CLTEXTLIB   			E:\work\SDK\60\SR7\jre\bin\nio
1CLTEXTCLLOD   	ClassLoader loaded classes
2CLTEXTCLLOAD  		Loader *System*(0x100BFE98)
3CLTEXTCLASS   			sun/net/www/MessageHeader(0x03300090)
3CLTEXTCLASS   			java/io/FilePermission(0x03300590)
3CLTEXTCLASS   			java/io/FilePermissionCollection(0x03300AB0)
3CLTEXTCLASS   			java/security/AllPermission(0x03300E00)
3CLTEXTCLASS   			java/security/BasicPermissionCollection(0x03300FB0)
 



8. まとめ

このページではWAS v7環境のjavacoreの中身をご紹介しました。
最後に一般的な障害の種類別に確認ポイントとセクションをまとめてみました。

全ての障害


この3つのセクションで基本情報(シグナルや発生日時、バージョン情報など)を確認しましょう。
TITLEセクションで Dump Event が GPF のときはクラッシュです。
TITLEセクションで Dump Event が OutOfMemoryError のときはOutOfMemoryErrorです。
TITLEセクションで Dump Event が user のときはこのjavacoreは手動で取得されたことを示しています。



クラッシュのとき


THREADSセクションでクラッシュが発生したスレッドのスタックを確認します。
特にスタックの一番上がクラッシュ実行時にスレッドなので要注意です。
そのスレッドを持つクラスがどのクラスローダーからロードされたかを調べる場合はCLASSESセクションを見ましょう。


OutOfMemoryError(OOM) のとき


メモリーの空き容量をMEMINFOセクションで確認します。
Javaヒープサイズの空き容量が分かります。
Javaヒープサイズに空き容量がほとんどなかったらJavaヒープのOOMです。
Javaヒープサイズに空き容量があるにも関わらずOOMが発生している場合には、フラグメンテーション(Javaヒープの断片化)かNative OOMが疑われます。
THREADSセクションでメモリーを大量に消費するような怪しいスレッドが動いていないかどうかを確認します。


ハングのとき


ハング中に複数回javacoreを取得しましょう。(2分おきに3回くらい)
LOCKSセクションでデッドロックの有無を調べます。
また、同じくLOCKSセクションで、1つのロックに長い待ち行列ができてないかを調べます。
もし1つのロックで長い待ち行列ができていたら、THREADSセクションでそのスレッドのスタックの最上部を確認し、なぜ処理が遅延しているのかを調べます。
複数のjavacoreを比較し、ハングの原因となっているスレッドの時間経過を確認します。


クラスロード系の例外のとき


THREADSセクションで例外が発生したスレッドのスタックを見て、どのメソッドの処理でこの例外が派生したかを確認します。
CLASSESセクションで例外の対象となったクラスがロードされたクラスローダーを確認します。


以上です。


今日: - 昨日: - 累計: -
ツールボックス

下から選んでください:

新しいページを作成する
ヘルプ / FAQ もご覧ください。