CPU のボトルネック
vmstat がシステムに CPU 制約があることを示している場合、次に行うべきことは、どのプロセスが CPU 時間を最も多用しているのかを判別することです。
推奨されるツールは、tprof です。
> tprof -s -k -x sleep 60Mon Nov 28 12:40:11 2010
System: AIX 6.1 Node: voodoo Machine: 00455F1B4C00
Starting Command sleep 60
stopping trace collection
Generating sleep.prof
> cat sleep.prof
Process Freq Total Kernel User Shared Other
======= ==== ===== ====== ==== ====== =====
./java 5 59.39 24.28 0.00 35.11 0.00
wait 4 40.33 40.33 0.00 0.00 0.00
/usr/bin/tprof 1 0.20 0.02 0.00 0.18 0.00
/etc/syncd 3 0.05 0.05 0.00 0.00 0.00
/usr/bin/sh 2 0.01 0.00 0.00 0.00 0.00
gil 2 0.01 0.01 0.00 0.00 0.00
afsd 1 0.00 0.00 0.00 0.00 0.00
rpc.lockd 1 0.00 0.00 0.00 0.00 0.00
swapper 1 0.00 0.00 0.00 0.00 0.00
======= ==== ===== ====== ==== ====== =====
Total 20 100.00 64.70 0.00 35.29 0.00
Process PID TID Total Kernel User Shared Other
======= === === ===== ====== ==== ====== =====
./java 467018 819317 16.68 5.55 0.00 11.13 0.00
./java 467018 766019 14.30 6.30 0.00 8.00 0.00
./java 467018 725211 14.28 6.24 0.00 8.04 0.00
./java 467018 712827 14.11 6.16 0.00 7.94 0.00
wait 20490 20491 10.24 10.24 0.00 0.00 0.00
wait 8196 8197 10.19 10.19 0.00 0.00 0.00
wait 12294 12295 9.98 9.98 0.00 0.00 0.00
wait 16392 16393 9.92 9.92 0.00 0.00 0.00
/usr/bin/tprof 421984 917717 0.20 0.02 0.00 0.18 0.00
/etc/syncd 118882 204949 0.04 0.04 0.00 0.00 0.00
./java 467018 843785 0.03 0.02 0.00 0.00 0.00
gil 53274 73765 0.00 0.00 0.00 0.00 0.00
gil 53274 61471 0.00 0.00 0.00 0.00 0.00
/usr/bin/sh 397320 839883 0.00 0.00 0.00 0.00 0.00
rpc.lockd 249982 434389 0.00 0.00 0.00 0.00 0.00
/usr/bin/sh 397318 839881 0.00 0.00 0.00 0.00 0.00
swapper 0 3 0.00 0.00 0.00 0.00 0.00
afsd 65776 274495 0.00 0.00 0.00 0.00 0.00
/etc/syncd 118882 258175 0.00 0.00 0.00 0.00 0.00
/etc/syncd 118882 196839 0.00 0.00 0.00 0.00 0.00
======= === === ===== ====== ==== ====== =====
Total 100.00 64.70 0.00 35.29 0.00
Total Samples = 24749 Total Elapsed Time = 61.88s467018 の Java™ プロセスが CPU 時間の大部分を使用していることを示しています。 その CPU 時間が、そのプロセスの中で 4 つのスレッド (スレッド ID 819317、766019、725211、および 712827) によって共有されていることも分かります。各列が何を表しているのかを理解することで、これらのスレッドの実行内容を理解することができます。
- 合計
- このスレッドまたはプロセスが使用した CPU 時間の合計パーセント。
- カーネル
- カーネル・ルーチンの中でこのスレッドまたはプロセスが (JVM または他のネイティブ・コードの要求により) 消費した CPU 時間の合計パーセント。
- ユーザー
- 実行可能プログラム内のルーチンの実行に消費した CPU 時間の合計パーセント。 Java 実行可能ファイルは、共有ライブラリーから JVM をロードするシン・ラッパーであるため、この CPU 時間は非常に小さいかゼロであることが予期されます。
- 共有
- 共有ライブラリー内のルーチンの実行に消費した CPU 時間の合計パーセント。 このカテゴリーの下に示された時間には、JVM 自体、JIT コンパイル動作 (生成されたコードの実行ではありません)、およびその他のすべてのネイティブ JNI コードによって実行された作業に要した時間が含まれています。
- その他
- Kernel、User、および Shared に含まれない CPU 時間の合計パーセント。 Java プロセスの場合、この CPU 時間は、Java バイトコードおよび JIT コンパイル・メソッド自体の実行をカバーします。
前の例から、カーネルと共有の値に注目してください。これらの値は、このプロセスによって使用されるすべての CPU 時間を表し、Java プロセスが JVM (またはその他のネイティブ・コード) 内で作業を行うために時間を費やしていることを示します。
Kernel および Shared の時間中に実行されていた内容を理解するには、tprof 出力の関連するセクションを分析します。
共有ライブラリー・セクションには、どの共有ライブラリーが呼び出されているのかが示されています。
Shared Object %
============= ======
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9gc26.so 17.42
/usr/lib/libc.a[shr.o] 9.38
/usr/lib/libpthreads.a[shr_xpg5.o] 6.94
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9thr26.so 1.03
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9prt26.so 0.24
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9vm26.so 0.10
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9ute26.so 0.06
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9jit26.so 0.05
/usr/lib/libtrace.a[shr.o] 0.04
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9trc26.so 0.02
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9hookable26.so 0.01このセクションは、ほとんどすべての時間が 1 つの特定の共有ライブラリーで費やされていることを示しています。これは、JVM インストールの一部です。 libj9gc<vm_version>.soここで、 < vm_version> は、 J9 仮想マシンのバージョンです ( java -version コマンドの出力を調べて、VM レベルを確認します)。 比較的使用頻度の高い JVM ライブラリーが実行する機能を理解することで、スレッドの実行内容をより正確に把握できるようになります。
- libbcv<vm_version>.so
- バイトコード・ベリファイヤー
- libdbg<vm_version>.so
- デバッグ・サーバー (Java デバッグ・インターフェースで使用)
- libj9gc<vm_version>.so
- ガーベッジ・コレクション
- libj9jextract.so
- ダンプ抽出ツール (jextract コマンドによって使用)
- libj9jit<vm_version>.so
- Just In Time (JIT) コンパイラー
- libj9jvmti<vm_version>.so
- JVMTI インターフェース
- libj9prt<vm_version>.so
- JVM とオペレーティング・システムの間のポート層
- libj9shr<vm_version>.so
- 共有クラス・ライブラリー
- libj9thr<vm_version>.so
- スレッド化ライブラリー
- libj9ute<vm_version>.so
- トレース・エンジン
- libj9vm<vm_version>.so
- コア仮想マシン
- libj9zlib<vm_version>.so
- 圧縮ファイル用ユーティリティー・ライブラリー
- libjclscar_<vm_version>.so
- Java クラス・ライブラリー (JCL) サポート・ルーチン
上記の例では、CPU 時間がガーベッジ・コレクション (GC) 実装の内部で消費されています。これは、GC に問題があるか、GC がほぼ連続的に実行されていることを示しています。
ここでも、 tprof 出力の関連セクションを分析することにより、CPU 時間中に libj9gc<vm_version>.so ライブラリー内で何が発生しているかをより正確に理解することができます。
Profile: /work/JDK/inst.images/rios_aix32_9/sdk/bin/
libj9gc26.so
Total % For All Processes (/work/JDK/inst.images/rios_aix32_9/
sdk/bin/libj9gc26.so) = 17.42
Subroutine % Source
========== ====== ======
Scheme::scanMixedObject(MM_Environment*,J9Object*) 2.67 MarkingScheme.cpp
MarkingScheme::scanClass(MM_Environment*,J9Class*) 2.54 MarkingScheme.cpp
.GC_ConstantPoolObjectSlotIterator::nextSlot() 1.96 jectSlotIterator.cpp
lelTask::handleNextWorkUnit(MM_EnvironmentModron*) 1.05 ParallelTask.cpp
orkPackets::getPacket(MM_Environment*,MM_Packet**) 0.70 WorkPackets.cpp
cheme::fixupRegion(J9Object*,J9Object*,bool,long&) 0.67 CompactScheme.cpp
WorkPackets::putPacket(MM_Environment*,MM_Packet*) 0.47 WorkPackets.cpp
rkingScheme::scanObject(MM_Environment*,J9Object*) 0.43 MarkingScheme.cpp
sweepChunk(MM_Environment*,MM_ParallelSweepChunk*) 0.42 allelSweepScheme.cpp
ment*,J9IndexableObject*,J9Object**,unsigned long) 0.38 MarkingScheme.cpp
M_CompactScheme::getForwardingPtr(J9Object*) const 0.36 CompactScheme.cpp
ObjectHeapIteratorAddressOrderedList::nextObject() 0.33 dressOrderedList.cpp
ckets::getInputPacketFromOverflow(MM_Environment*) 0.32 WorkPackets.cpp
.MM_WorkStack::popNoWait(MM_Environment*) 0.31 WorkStack.cpp
WorkPackets::getInputPacketNoWait(MM_Environment*) 0.29 WorkPackets.cpp
canReferenceMixedObject(MM_Environment*,J9Object*) 0.29 MarkingScheme.cpp
MarkingScheme::markClass(MM_Environment*,J9Class*) 0.27 MarkingScheme.cpp
._ptrgl 0.26 ptrgl.s
_MarkingScheme::initializeMarkMap(MM_Environment*) 0.25 MarkingScheme.cpp
.MM_HeapVirtualMemory::getHeapBase() 0.23 eapVirtualMemory.cppこの出力から、最も使用時間の長い関数が以下のものであることが分かります。
MarkingScheme::scanMixedObject(MM_Environment*,J9Object*)
2.67 MarkingScheme.cpp
MarkingScheme::scanClass(MM_Environment*,J9Class*)
2.54 MarkingScheme.cpp
ObjectSlotIterator.GC_ConstantPoolObjectSlotIterator::nextSlot()
1.96 ObjectSlotIterator.cpp
ParallelTask::handleNextWorkUnit(MM_EnvironmentModron*)
1.05 ParallelTask.cpp各値は、GC の Mark フェーズで時間が消費されていることを示しています。 この出力には Compact フェーズおよび Sweep フェーズへの参照も含まれているため、おそらく GC は完了していますが、連続的に実行されていると考えられます。 -verbosegcを有効にして実行することで、その可能性を確認できます。
CPU 時間の大半が Kernel 列および Shared 列に示されているケースでは、上記と同じ方法論を使用できます。 ただし、CPU 時間が以下のように分類されているとします。Othertprof には、実行されている Java メソッドを正しく詳述するセクションが含まれていないため、別の方法が必要です。
CPU 時間の起因となっている場合OtherJavadump を使用して、CPU 時間を消費していることが示されている TID のスタック・トレースを判別し、実行している作業のアイデアを提供することができます。 tprof の出力に示されている TID の値を、Javadump 内の適切なスレッドに対応させます。これを行うには、10 進数で示されている tprof の TID を取得し、16 進数に変換します。 16 進値は、以下のように表示されます。native IDJavadump に記録されています。
前述の例の場合:
Process PID TID Total Kernel User Shared Other
======= === === ===== ====== ==== ====== =====
./java 7018 819317 16.68 5.55 0.00 11.13 0.00このスレッドは、最も多くのCPUを占めるスレッドです。10進数のTIDは819317です。 この値は16 進数のC8075で、Javadumpに表示されます。
3XMTHREADINFO "main" (TID:0x300E3500, sys_thread_t:0x30010734,
state:R, native ID:0x000C8075) prio=5
4XESTACKTRACE at java/lang/Runtime.gc(Native Method)
4XESTACKTRACE at java/lang/System.gc(System.java:274)
4XESTACKTRACE at GCTest.main(GCTest.java:5)これらのエントリーは、この場合、スレッドが GC を呼び出していることを示し、 libj9gc<vm_version>.so 共有ライブラリーにかかった時間を説明します。