哪个Java线程占用了CPU?

73
假设您的Java程序使用100%的CPU。 它有50个线程。 您需要找到哪个线程有问题。 我没有找到可以帮助的工具。 目前,我使用以下非常耗时的例程:
  1. 运行jstack <pid>,其中pid是Java进程的进程ID。 找到它的简单方法是运行JDK中包含的另一个实用程序 - jps。 最好将jstack的输出重定向到文件。
  2. 搜索“可运行”线程。 跳过那些等待套接字的线程(出于某种原因,它们仍然标记为可运行)。
  3. 重复步骤1和2几次,看看是否能找到模式。

或者,您可以在Eclipse中附加到Java进程,并尝试挂起一个接一个的线程,直到找到占用CPU的线程。 在一台单CPU的机器上,您可能需要首先降低Java进程的优先级才能四处移动。 即使这样,由于超时,Eclipse通常也无法附加到正在运行的进程。

我本来期望Sun的visualvm工具可以做到这一点。

有人知道更好的方法吗?


https://dev59.com/XnRA5IYBdhLWcg3w_DHF#28408974 - Kanagavelu Sugumar
12个回答

95

如何在生产服务器中确定哪个Java线程消耗了最多的CPU。

大多数(如果不是全部)执行重要任务的生产系统将使用多个Java线程。当有问题发生并且CPU使用率达到100%时,很难确定哪个线程(或哪些线程)造成了这种情况。直到有人比我聪明地向我展示了如何完成它。在这里,我将向您展示如何做到这一点,以便您也可以通过您的极客技能惊叹您的家人和朋友。

一个测试应用程序

为了进行测试,我们需要一个测试应用程序。我会提供一个给你。它由三个类组成:

  • 一个HeavyThread类,用于执行一些CPU密集型操作(计算MD5哈希值)
  • 一个LightThread类,用于执行一些不那么CPU密集型的操作(计数和睡眠)。
  • 一个StartThreads类,用于启动1个CPU密集型和多个轻型线程。

以下是这些类的代码:

import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
import java.util.UUID;

/**
 * thread that does some heavy lifting
 *
 * @author srasul
 *
 */
public class HeavyThread implements Runnable {

        private long length;

        public HeavyThread(long length) {
                this.length = length;
                new Thread(this).start();
        }

        @Override
        public void run() {
                while (true) {
                        String data = "";

                        // make some stuff up
                        for (int i = 0; i < length; i++) {
                                data += UUID.randomUUID().toString();
                        }

                        MessageDigest digest;
                        try {
                                digest = MessageDigest.getInstance("MD5");
                        } catch (NoSuchAlgorithmException e) {
                                throw new RuntimeException(e);
                        }

                        // hash the data
                        digest.update(data.getBytes());
                }
        }
}


import java.util.Random;

/**
 * thread that does little work. just count & sleep
 *
 * @author srasul
 *
 */
public class LightThread implements Runnable {

        public LightThread() {
                new Thread(this).start();
        }

        @Override
        public void run() {
                Long l = 0l;
                while(true) {
                        l++;
                        try {
                                Thread.sleep(new Random().nextInt(10));
                        } catch (InterruptedException e) {
                                e.printStackTrace();
                        }
                        if(l == Long.MAX_VALUE) {
                                l = 0l;
                        }
                }
        }
}


/**
 * start it all
 *
 * @author srasul
 *
 */
public class StartThreads {

        public static void main(String[] args) {
                // lets start 1 heavy ...
                new HeavyThread(1000);

                // ... and 3 light threads
                new LightThread();
                new LightThread();
                new LightThread();
        }
}

假设你从未见过这段代码,你手头只有一个运行这些类并且占用100% CPU 的Java进程的PID。

首先让我们从StartThreads类开始。

$ ls
HeavyThread.java  LightThread.java  StartThreads.java
$ javac *
$ java StartThreads &

目前有一个Java进程正在运行,它应该占用了100%的CPU。在我的top命令中,我看到:

top命令截图

在top命令中按Shift-H键,可以打开线程信息。top命令的man手册中写道:

   -H : Threads toggle
        Starts top with the last remembered 'H' state reversed.  When
        this  toggle is On, all individual threads will be displayed.
        Otherwise, top displays a  summation  of  all  threads  in  a
        process.

现在我打开了Threads显示功能,在顶部看到如下截图: top screenshot with threads displayed

我有一个PID为28294java进程。使用jstack获取该进程的堆栈转储:

$ jstack 28924
2010-11-18 13:05:41
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.0-b16 mixed mode):

"Attach Listener" daemon prio=10 tid=0x0000000040ecb000 nid=0x7150 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f9a98027800 nid=0x70fd waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-3" prio=10 tid=0x00007f9a98025800 nid=0x710d waiting on condition [0x00007f9a9d543000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-2" prio=10 tid=0x00007f9a98023800 nid=0x710c waiting on condition [0x00007f9a9d644000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-1" prio=10 tid=0x00007f9a98021800 nid=0x710b waiting on condition [0x00007f9a9d745000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
    at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
    at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
    at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
    at java.security.MessageDigest.update(MessageDigest.java:293)
    at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
    - locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
    - locked <0x00007f9aa457e708> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
    at java.util.UUID.randomUUID(UUID.java:162)
    at HeavyThread.run(HeavyThread.java:27)
    at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x00007f9a98006800 nid=0x7108 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00007f9a98004000 nid=0x7107 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00007f9a98001000 nid=0x7106 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000040de4000 nid=0x7105 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000040dc4800 nid=0x7104 in Object.wait() [0x00007f9a97ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000040dbd000 nid=0x7103 in Object.wait() [0x00007f9a9de92000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0000000040db8800 nid=0x7102 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000040d6e800 nid=0x70fe runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000040d70800 nid=0x70ff runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040d72000 nid=0x7100 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040d74000 nid=0x7101 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f9a98011800 nid=0x7109 waiting on condition 

JNI global references: 910
从我的顶部我可以看到顶级线程的PID是28938。而28938以十六进制表示是0x710A。请注意,在堆栈转储中,每个线程都有一个以十六进制表示的nid。恰好0x710A是该线程的ID。
"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
    at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
    at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
    at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
    at java.security.MessageDigest.update(MessageDigest.java:293)
    at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
    - locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
    - locked <0x00007f9aa457e708> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
    at java.util.UUID.randomUUID(UUID.java:162)
    at HeavyThread.run(HeavyThread.java:27)
    at java.lang.Thread.run(Thread.java:619)

因此,您可以确认运行 HeavyThread 类的线程正在消耗大部分 CPU。

在实际情况中,可能是一堆线程消耗了一部分 CPU,这些线程加在一起会导致 Java 进程使用 100% 的 CPU。

摘要

  • 运行 top 命令
  • 按 Shift-H 查看线程视图
  • 获取具有最高 CPU 的线程的进程 ID
  • 将进程 ID 转换为十六进制
  • 获取 Java 进程的堆栈转储
  • 查找具有匹配十六进制 PID 的线程。

这是一个非常好的方法。我相信当您不管理线程时,这种方法可能无法工作,而在使用Play等框架时通常会出现这种情况。 - Arul Dhesiaseelan
6
好的,请提供需要翻译的内容。 - okigan
很棒的帖子,完美运作。在谷歌中输入“xxx in hex”即可获得十六进制。在Ubuntu16上一定需要小写。 - otter606
4
在*nix系统中,我使用_printf 0x%x pid_来获取十六进制值。 - Micha Kops
谢谢,这对我很有帮助!你也可以使用 kill -3 <PID> 命令在标准输出中获取 Java 进程的完整线程转储。 - tsl0922
显示剩余3条评论

22

jvmtop可以展示给您消耗最多的线程:

    TID NAME                                 STATE     CPU    TOTALCPU
     25 http-8080-Processor13                RUNNABLE  4.55%     1.60%
 128022 RMI TCP Connection(18)-10.101.       RUNNABLE  1.82%     0.02%
  36578 http-8080-Processor164               RUNNABLE  0.91%     2.35%
 128026 JMX server connection timeout   TIMED_WAITING  0.00%     0.00%

2
有人知道如何将这个TID与线程转储相关联吗?它们与我在线程转储中看到的“tid”或“nid”标识符不匹配(在将它们转换为十六进制后)。 - Tom
这对我的使用非常完美。 - Sanjiv Jivan

20

1
我尝试了Bruce Chapman的命令行Hot Thread检测器,它对我很有效(它需要从tools.jar中获取一些类,所以我不得不将tools.jar复制到我的Ubuntu Jaunty(9.04)上的jre/lib/ext目录下,使用Sun Java 6更新13)。在这种情况下,我更喜欢使用命令行工具,因为系统通常非常缓慢,GUI工具真的很痛苦。 - Gene Vayngrib
6
五年后,布鲁斯·查普曼(Bruce Chapman)文件的链接不再起作用。尽管如此,您仍然可以阅读他的帖子,但无法下载任何文件。 - Eduardo Bezerra
@EduardoBezerra:下载似乎又可以正常工作了。 - serv-inc

11

只需运行JVisualVM,连接到您的应用程序,并使用线程视图。持续活动的那个线程最有可能是罪魁祸首。


1
即使使用JConsole(随Java 1.5及以上版本捆绑),您也可以执行相同的操作。 - adrian.tarau
1
JVisualVM也随J6捆绑安装。 - Lawrence Dol
任何商业 Java 分析工具都可以做同样的事情,如果由于某种原因你卡在早期版本的 JDK 上。 - Bill Michell
@Bill:很好的观点。我个人多年来一直使用 JProfiler 与 Java 1 的代码,并发现它非常有效。 - Lawrence Dol
谢谢。JVisualVM确实显示线程是否可运行。但这并不意味着它们实际上正在运行,有些可能会停留在套接字上 - 不确定为什么它们仍然被标记为可运行 - 请注意,在JVisualVM线程视图中,一些线程始终是绿色的。因此,它可能会给您一个想法,但不能确定哪个线程正在占用CPU。 - Gene Vayngrib
是的,似乎JVM认为除了wait()之外的任何本地方法中的线程都在运行。这很烦人,但仍然很容易排除它们以找到真正的罪魁祸首。 - Lawrence Dol

6

谢谢,下次如果我遇到100%的CPU占用问题,我会比较Bruce的命令行工具和这个插件。 - Gene Vayngrib

4
我建议你看一下由阿里巴巴开源的工具Arthas
它包含许多有用的命令,可帮助您调试生产环境中的代码:
  • Dashboard:Java进程概览
  • SC:搜索JVM加载的类
  • Jad:将类反编译为源代码
  • Watch:查看方法调用输入和结果
  • Trace:找到方法调用的瓶颈
  • Monitor:查看方法调用统计信息
  • Stack:查看方法的调用堆栈
  • Tt:方法调用时间隧道
以下是仪表板示例:dashboard

2
如果你在Windows系统下运行,可以尝试使用Process Explorer。打开你的进程属性对话框,然后选择线程选项卡。

我们刚刚使用了这种方法来定位线程循环,效果很好。Eclipse的调试视图非常适合启动和停止线程。您可以暂停所有线程,然后逐个重新激活它们,以查看哪个正在自旋。 - Jim Ferrans
你也可以使用这种方法来查找问题线程,记录线程ID,使用Java Visual VM进行线程转储,并通过比较线程ID找到问题线程的名称。(请注意,Java VisualVM线程ID标记为nid,并且它是十六进制的) - Reid

2
使用ps -eLtop -H -p <pid>,如果您需要实时查看和监控,请运行top(然后按shift H),以获取与java进程相关联的轻量级进程(LWP,也称为线程)。
root@xxx:/# ps -eL
PID LWP TTY TIME CMD
 1 1 ? 00:00:00 java
 1 7 ? 00:00:01 java
 1 8 ? 00:07:52 java
 1 9 ? 00:07:52 java
 1 10 ? 00:07:51 java
 1 11 ? 00:07:52 java
 1 12 ? 00:07:52 java
 1 13 ? 00:07:51 java
 1 14 ? 00:07:51 java
 1 15 ? 00:07:53 java
…
 1 164 ? 00:00:02 java
 1 166 ? 00:00:02 java
 1 169 ? 00:00:02 java

注意:LWP代表轻量级进程;在Linux中,线程与进程相关联,以便可以在内核中进行管理;LWP与父进程共享文件和其他资源。现在让我们看看占用最多时间的线程。

 1 8 ? 00:07:52 java
 1 9 ? 00:07:52 java
 1 10 ? 00:07:51 java
 1 11 ? 00:07:52 java
 1 12 ? 00:07:52 java
 1 13 ? 00:07:51 java
 1 14 ? 00:07:51 java
 1 15 ? 00:07:53 java

Jstack 是一个 JDK 工具,用于打印 Java 堆栈;它打印出以下形式的进程线程。

还要熟悉其他酷炫的 JDK 工具(如 jcmd jstat jhat jmap jstack 等 - https://docs.oracle.com/javase/8/docs/technotes/tools/unix/)。

jstack -l <process id>

在堆栈跟踪中的 nid,即本地线程 id,是与 linux 中的 LWT 相连的线程(https://gist.github.com/rednaxelafx/843622)。

“GC task thread#0 (ParallelGC)” os_prio=0 tid=0x00007fc21801f000 nid=0x8 runnable

该nid以十六进制给出;因此,我们将花费最长时间的线程id转换为8、9、10、11、12、13、14、15在DEC中的值= 8、9、A、B、C、D、E、F在HEX中。

(请注意,此特定堆栈来自带有方便过程的Java Docker容器,值为1) 让我们看一下具有这些ID的线程。

“GC task thread#0 (ParallelGC)” os_prio=0 tid=0x00007fc21801f000 nid=0x8 runnable
“GC task thread#1 (ParallelGC)” os_prio=0 tid=0x00007fc218020800 nid=0x9 runnable
“GC task thread#2 (ParallelGC)” os_prio=0 tid=0x00007fc218022800 nid=0xa runnable
“GC task thread#3 (ParallelGC)” os_prio=0 tid=0x00007fc218024000 nid=0xb runnable
“GC task thread#4 (ParallelGC)” os_prio=0 tid=0x00007fc218026000 nid=0xc runnable
“GC task thread#5 (ParallelGC)” os_prio=0 tid=0x00007fc218027800 nid=0xd runnable
“GC task thread#6 (ParallelGC)” os_prio=0 tid=0x00007fc218029800 nid=0xe runnable
“GC task thread#7 (ParallelGC)” os_prio=0 tid=0x00007fc21802b000 nid=0xf runnable

所有GC相关的线程;难怪它占用了大量CPU时间;但问题是GC在这里是个问题吗。 使用jstat(而不是jstack!)实用程序快速检查GC。 >

1

取一个线程转储。等待10秒钟。再取一个线程转储。重复一次。 检查线程转储并查看哪些线程卡在同一位置或处理相同请求。 这是一种手动的方法,但通常很有用。


0

这是一种有点hacky的方法,但似乎你可以在调试器中启动应用程序,然后暂停所有线程,通过代码找出哪个线程没有在某种循环中阻塞锁或I/O调用。或者这就像你已经尝试过的?


是的,这差不多就是我在做的事情。但这相当繁琐,特别是如果有许多线程并且在单CPU机器上运行时,这是小型EC2实例和在VirtualBox中运行的情况。 - Gene Vayngrib

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接