CPU使用時間の多いスレッドを特定する
仕事であるアプリケーションのCPU使用率が異常に高くなる事象のトラシューをしたんですが、久々にこの手のトラシューをしていろいろ忘れてたこともあり、新たな学びもあったりしたので、備忘録として残しておく。
とりあえずこの手の事象に遭遇した際はスレッドダンプ取得して、CPU負荷の高そうな処理、スレッドの特定をしていくわけですが、今回は「CPU使用時間が多いスレッドの特定方法」について書こうかなと思います。
スレッドダンプの取得方法については昔の記事で書いてます。
手順としては以下のことをやれば特定できます。
- top でスレッド情報まで含めてアプリ内でCPU使用時間が多いスレッドのPIDを特定する
- 上記PIDの16進数を計算する
- 計算した16進数の tid を持つスレッドをスレッドダンプで特定する
1. top でCPU使用時間が多いスレッドのPIDを特定する
top に H オプションをつけるとスレッドまで含んだ情報を出力してくれる。 c オプションをつけておくとコマンドをプログラム名で出してくれるので対象を見つけやすい。
# top -cH top - 16:12:30 up 21 min, 1 user, load average: 0.08, 0.02, 0.02 Threads: 112 total, 2 running, 110 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.0 us, 0.3 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 805.8 total, 142.1 free, 165.8 used, 497.9 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 502.1 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 13483 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.05 java ThreadSample 13484 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13485 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13486 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13487 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13488 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13489 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13490 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample 13491 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.09 java ThreadSample 13492 root 20 0 2120212 26476 16240 S 0.0 3.2 0:00.00 java ThreadSample
2. 上記PIDの16進数を計算する
上記の例だと対してCPU使用時間は高くないですが、今回は「13491」が高いとする。 これの16進数を計算すると「34B3」になる。
3. スレッドダンプで使用時間が多いスレッドを特定する
スレッドダンプで nid が「34B3」のやつがCPU使用時間が多いスレッドになる。 nid(Native Thread IDの略らしく)がOSのTIDになります。
2021-05-14 16:13:07 Full thread dump OpenJDK 64-Bit Server VM (25.292-b10 mixed mode): "Attach Listener" #10 daemon prio=9 os_prio=0 tid=0x00007f1a68001000 nid=0x34cd waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "DestroyJavaVM" #9 prio=5 os_prio=0 tid=0x00007f1a9004c800 nid=0x34ab waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Thread-0" #8 prio=5 os_prio=0 tid=0x00007f1a90141000 nid=0x34b4 waiting on condition [0x00007f1a7e57a000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at SubThread.run(ThreadSample.java:13) "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f1a9011d800 nid=0x34b2 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f1a9011b000 nid=0x34b1 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f1a9010e800 nid=0x34b0 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f1a9010b000 nid=0x34af runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f1a900db000 nid=0x34ae in Object.wait() [0x00007f1a7f2b8000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000000f3608ee8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144) - locked <0x00000000f3608ee8> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216) "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f1a900d6800 nid=0x34ad in Object.wait() [0x00007f1a7f3b9000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000000f3606c00> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) - locked <0x00000000f3606c00> (a java.lang.ref.Reference$Lock) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "VM Thread" os_prio=0 tid=0x00007f1a900cc800 nid=0x34ac runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007f1a90120800 nid=0x34b3 waiting on condition JNI global references: 5
トラシューして感じたのは、topコマンドの出力、スレッドダンプ、あとこの界隈だと GCログ、ヒープダンプについていつも雰囲気で読んでいてちゃんと読める知識がないなぁということ。 このあたり、今一度ちゃんと勉強しないとなと思いました。
今日のところは以上です。