52 如何通过工具或jdk命令来定位性能瓶颈
Diego38 50 1

1. 前言

Java应用,无一不是多线程的,多线程涉及的问题很多,如果要提升系统的性能,定位系统性能瓶颈需要首先监控运行状态才能从代码着手优化。

本节将模拟一些常见的场景,然后通过工具来演示分析定位的过程。

2. 模拟大量锁等待场景问题,演示排查过程

首先构造一个多线程等待的场景,这批线程处理同样的任务,任务耗时较久,需要加锁排队处理,依次模拟锁等待的场景。

public class LongWaitTest {

    private static ReentrantLock lock = new ReentrantLock();

    public static void main(String[] args) {
        ExecutorService fixedThreadPool = Executors.newFixedThreadPool(100);
        for (int i = 0; i < 50; i++) {
            fixedThreadPool.submit(() -> {
                lock.lock();
                try {
                    System.out.println("获取锁成功");
                    Thread.sleep(100000);
                } catch (InterruptedException e) {

                } finally {
                    lock.unlock();
                }
            });
        }

    }
}

通过JDK的jstack命令(thread dump命令),可以通过输出thread dump得到每个线程具体的运行状态,还是先通过jps命令列出所有java进程的pid,然后通过jstack 得到如下线程堆栈。

"pool-1-thread-5" #15 prio=5 os_prio=31 tid=0x00007fac718b8000 nid=0x5b03 waiting on condition [0x0000700010fc9000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ad4a5a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at com.mooc.study.thread.LongWaitTest.lambda$main$0(LongWaitTest.java:15)
    at com.mooc.study.thread.LongWaitTest$$Lambda$1/1555093762.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-1-thread-4" #14 prio=5 os_prio=31 tid=0x00007fac718b7000 nid=0xa603 waiting on condition [0x0000700010ec6000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ad4a5a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at com.mooc.study.thread.LongWaitTest.lambda$main$0(LongWaitTest.java:15)
    at com.mooc.study.thread.LongWaitTest$$Lambda$1/1555093762.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

"pool-1-thread-3" #13 prio=5 os_prio=31 tid=0x00007fac718b6800 nid=0x5903 waiting on condition [0x0000700010dc3000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ad4a5a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at com.mooc.study.thread.LongWaitTest.lambda$main$0(LongWaitTest.java:15)
    at com.mooc.study.thread.LongWaitTest$$Lambda$1/1555093762.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

我们看到即使线程都处于WAITING状态,也不代表线程是健康运行的,因为WAITING时由可能在等待锁的释放,比如上述输出,线程都卡在ReentrantLock.lock中。如果锁被替换成Synchronized,那么上述的输出状态将是BLOCKED, 这个试验留给大家来完成。

3. 模拟CPU高使用率场景,演示排查过程

在实际生产环境中,有多种情况会引发CPU飙升的问题,常见是垃圾回收,频繁的垃圾回收线程消耗大量的CPU,另外就是代码写的有问题,产生了死循环,除此以外,就是系统流量较大,在CPU密集型的应用中,就会首先造成CPU飙升。

下面以一个代码案例来说明下发生和排查过程。

public class BusyCPU {

    public static void main(String[] args) {
        ExecutorService fixedThreadPool = Executors.newFixedThreadPool(100);
        //产生繁忙的cpu使用
        fixedThreadPool.submit(() -> {
            try {
                while (true) {

                }
            } finally {
            }
        });
        //制造一个相对空闲的线程
        fixedThreadPool.submit(() -> {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            } finally {
            }
        });
    }
}

通过执行arthas,执行命令./as.sh

选中我们的busyCPU进程后,可以在命令行中执行thread -n 10命令,即从高到低按顺序输出top 10个CPU使用高的线程。

[arthas@64349]$ thread -n 10
"pool-1-thread-1" Id=11 cpuUsage=96.74% deltaTime=197ms time=90160ms RUNNABLE
    at com.mooc.study.thread.BusyCPU.lambda$main$0(BusyCPU.java:14)
    at com.mooc.study.thread.BusyCPU$$Lambda$1/99550389.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)


"C1 CompilerThread3" [Internal] cpuUsage=0.2% deltaTime=0ms time=581ms


"arthas-command-execute" Id=29 cpuUsage=0.19% deltaTime=0ms time=18ms RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:448)
    at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:199)
    at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:122)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
    at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:385)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

通过arthas输出的堆栈可以发现,cpuUsage最高的是96.74% ,对应的堆栈是BusyCPU.java的第14行,这样可以快速定位消耗CPU较高的线程堆栈,从而可以有针对性的进行优化。

4. 总结

本节通过代码模拟锁等待和CPU使用率100%的场景,通过JDK命令Jstack和Arthas来定位排查问题,Jstack比较简单,就是一个纯输出线程堆栈的工具。Arthas是一个比较强大的工具,不仅能输出线程信息,类信息,以及运行时诊断都有很多可用的命令,值得深入去学习。

预览图
评论区

索引目录