在线上,我们经常会遇到jvm进程占用cpu很高的情况。产生这种现象的原因多种多样,可能是业务量突增,也可能是由于死循环或者递归无法跳出递归而造成。在这种情况下,我们需要快速的定位出占用cpu高的线程以及其代码的调用栈,以便我们能够快速的做出应对,无论是重启服务器还是代码回滚降级等操作。下文会给出两种方法用于快速定位问题。

测试代码

  public class Loop {
    public static void main(String []args) {
        long j = 0;
        while (j < Long.MAX_VALUE) {
            j++;
        }

        System.out.println(j);
    }
  }  

方案1 jstack或者jcmd

  • 查找Java对应的进程
    有很多方法比如jcmd, jps, 以及linux自带的 ps -ef|grep java
  • 列出进程中所有的线程
     top -H -p 5169
    

    这里的5169就是第一步查询出的进程号,上面的top命令执行后可以看到如下的效果,

    PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                     
     5170 zlover    20   0 2671888  26328  15564 R 78.0  0.9   2:45.64 java Loop                                   
     5169 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5171 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5172 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5173 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5174 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5175 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5176 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5177 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.00 java Loop                                   
     5178 zlover    20   0 2671888  26328  15564 S  0.0  0.9   0:00.09 java Loop
    
  • 根据列出的所有线程查找cpu占用率较高的线程 上面的线程中5170线程占用了很高的cpu,我们将其作为排查的目标
  • 将目标线程转换为16进制
    printf %x 5170
    

    上面的命令的输出结果是1432

  • 打印出当前所有线程的调用情况 使用jcmd和jstack都可以将线程调用情况打印出来,
    jstack 5169 > test
    jcmd 5169 Thread.print > test 
    
  • 在打印出的堆栈中查找线程

    打开test文件

5169:

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.91-b14 mixed mode):

"Attach Listener" #8 daemon prio=9 os_prio=0 tid=0x00007f2188001000 nid=0x145a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f21ac0b4000 nid=0x1439 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f21ac0b1000 nid=0x1438 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f21ac0ae800 nid=0x1437 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f21ac0ad000 nid=0x1436 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f21ac07a000 nid=0x1435 in Object.wait() [0x00007f21b153c000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000d0e08ee0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x00000000d0e08ee0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f21ac075800 nid=0x1434 in Object.wait() [0x00007f21b163d000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000d0e06b50> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000000d0e06b50> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007f21ac009800 nid=0x1432 runnable [0x00007f21b5749000]
   java.lang.Thread.State: RUNNABLE
	at Loop.main(Loop.java:5)

"VM Thread" os_prio=0 tid=0x00007f21ac06e000 nid=0x1433 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f21ac0b7000 nid=0x143a waiting on condition 

JNI global references: 9

在文件中搜索0x1432(1432就是刚才我们查询出的线程对应的十六进制线程号),就可以找到对应的线程以及其调用栈。 很明显当前的main函数 在执行loop方法。

方案2 JMC

JMC全称是java mission control, 可以用于动态跟踪jvm进程的状态,并进行数据统计。JMC的安装可以参照 http://www.oracle.com/technetwork/java/javaseproducts/mission-control/index.html来进行。

还是运行上面的程序,打开eclipse进入到jmc的视图,可以看到如下数据,

3306进程就是我们需要定位的进程,右键该进程会弹出三个选项

  • 启动jmx控制台
  • 启动飞行记录
  • 控制远程JMX代理

我们选择第二项,并且设置采样时长为15s

采样结束后会自动打开对应的数据并以图形化的方式展示给大家,在最最左侧的导航栏点击线程,

选择热点线程,可以看到

排在最前面的线程就是我们需要找的。我们还可以继续查看线程栈的情况,