プログラム日記

仕事であるアプリケーションのCPU使用率が異常に高くなる事象のトラシューをしたんですが、久々にこの手のトラシューをしていろいろ忘れてたこともあり、新たな学びもあったりしたので、備忘録として残しておく。

とりあえずこの手の事象に遭遇した際はスレッドダンプ取得して、CPU負荷の高そうな処理、スレッドの特定をしていくわけですが、今回は「CPU使用時間が多いスレッドの特定方法」について書こうかなと思います。

スレッドダンプの取得方法については昔の記事で書いてます。

a4dosanddos.hatenablog.com

手順としては以下のことをやれば特定できます。

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ログ、ヒープダンプについていつも雰囲気で読んでいてちゃんと読める知識がないなぁということ。このあたり、今一度ちゃんと勉強しないとなと思いました。

今日のところは以上です。