Javaプロセスの中でCPUを浪費しているスレッドを特定する

  • 27
    いいね
  • 5
    コメント

概要

Javaプロセスの中でCPUを浪費しているスレッドを特定する方法を紹介します。Linuxだけでなく、Windowsでの方法も載せています。

前提条件

JDKがインストールされていること

Linuxの場合

まずは、Linuxでの方法です。これと同じことがWindowsでも、できればいいわけです(後述します)。

(1) jpsコマンドで対象のJavaプロセスのIDを特定する

$ jps
25830 Jps
25800 EmbeddedJettyServer
25769 Launcher

(2) topコマンドで対象のJavaプロセスのスレッド単位のCPU使用状況を把握する

$ top -n 1 -H -p 25800

top - 21:29:39 up 23:36,  3 users,  load average: 1.66, 0.97, 0.52
Tasks:  31 total,   1 running,  30 sleeping,   0 stopped,   0 zombie
Cpu(s):  2.9%us,  0.8%sy,  0.0%ni, 96.2%id,  0.1%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3909512k total,  3778736k used,   130776k free,     9520k buffers
Swap:  2031612k total,    52248k used,  1979364k free,   366352k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                               
 25826 root      20   0 3912m 332m  16m R 95.9  8.7   1:34.14 java                                                                  
 25800 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.00 java                                                                  
 25804 root      20   0 3912m 332m  16m S  0.0  8.7   0:04.61 java                                                                  
 25805 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.59 java                                                                  
 25806 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.01 java                                                                  
 25807 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.02 java                                                                  
 25808 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.00 java                                                                  
 25809 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.00 java                                                                  
 25810 root      20   0 3912m 332m  16m S  0.0  8.7   0:00.00 java          

上の場合、PIDが「25826」のスレッドがCPUが95.9%を消費していることが分かります。

(3) 「25826」を以下のコマンドで16進数に変換します。

$ printf %x\\n 25826
64e2

(4) jstackコマンドで対象のJavaプロセスのスレッドダンプを取得する

$ jstack 25800 > thread_dump.txt

(5) thread_dump.txtをテキストエディタで開いて、nid=0x64e2で検索すれば、スレッドが特定できます。

"qtp2122049087-23" #23 prio=5 os_prio=0 tid=0x00007f5368f2b000 nid=0x64e2 runnable [0x00007f53a06b7000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.log4j.Category.getEffectiveLevel(Category.java:442)
        at org.apache.log4j.Category.isDebugEnabled(Category.java:736)
        at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:250)
        at org.t246osslab.easybuggy.troubles.InfiniteLoopServlet.doGet(InfiniteLoopServlet.java:24)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1507)
        at org.t246osslab.easybuggy.core.filters.AuthenticationFilter.doFilter(AuthenticationFilter.java:72)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
        at org.t246osslab.easybuggy.core.filters.SecurityFilter.doFilter(SecurityFilter.java:51)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
        at org.t246osslab.easybuggy.core.filters.EncodingFilter.doFilter(EncodingFilter.java:42)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1487)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)

Windowsの場合

(1) jpsコマンドで対象のJavaプロセスのIDを特定する

> jps
9488 Jps
5256 Launcher
3948 EmbeddedJettyServer

(2) Process Explorerで対象のJavaプロセスのスレッド単位のCPU使用状況を把握する

topコマンドの無いWindowsでは、Process Explorerというツールを使用します。ダウンロードして、exeファイルをクリックするだけで起動します。

pe64.png

対象のプロセスを見つけたら、右クリックして「Properties」をクリックします。

WS000001.JPG

次のようなウインドウが表示されるので、CPUを消費しているスレッドのTIDを確認します。

pe_sub.png

上の場合、PIDが「9292」のスレッドがCPUが26.47%を消費していることが分かります。

(3) 「9292」を関数電卓(Windowsなので)で16進数に変換します。

WS000002.JPG

「9292」の16進数は、244cです。

(4) jstackコマンドで対象のJavaプロセスのスレッドダンプを取得する

> jstack 3948 > thread_dmup.txt

(5) 出力したファイル(thread_dmup.txt)を開いて、nid=0x244cで検索すれば、スレッドが特定できます。

tdh1.png