Edited at

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

More than 1 year has passed since last update.


概要

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