Jstack 分析哪一行代码慢？jvm 打印出线程栈分析

悠悠 2021-09-25 04:56 267阅读 0赞

面试题：后台只有一台服务器，上线后发现，只有1个接口请求很慢，其他接口的请求和反应时间很正常，该怎么分析？怎么找出是哪行代码导致的慢？

是在线上，当然不能测试或单步调试。

**答案：打印出线程栈分析。**

什么是线程堆栈？  
线程栈：  
Java线程堆栈是某个时间对所有线程的一个快照，其中主要记录了如下信息  
– 线程的名称  
\- 线程的ID  
\- 原生线程ID  
\- 线程的运行状态  
\- 锁的状态  
\- 调用堆栈,也就是每个线程在各个方法调用的栈  
上面描述的信息，接下来我们会具体的介绍与分析

举例：

/**
     * @Author liuyazhou
     * @Date 2021/2/25 16:30
     * @Version 1.0
     * @Desc
     */
    
    
    /**
     * 同步线程
     */
    class SyncThread implements Runnable {
        private static int count;
    
        public SyncThread() {
            count = 0;
        }
    
        public synchronized static void method() {
            for (int i = 0; ; i++) {
                try {
                    System.out.println(Thread.currentThread().getName() + ":" + (count++));
                    Thread.sleep(100);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    
        public synchronized void run() {
            method();
        }
    }
    
    public class SynchronizedObject2 {
    
    
        public static void main(String[] args) {
            SyncThread syncThread1 = new SyncThread();
            SyncThread syncThread2 = new SyncThread();
            Thread thread1 = new Thread(syncThread1, "SyncThread1");
            Thread thread2 = new Thread(syncThread2, "SyncThread2");
            thread1.start();
            thread2.start();
        }
    }

输出：

SyncThread1:.......
    SyncThread1:81069
    SyncThread1:81070
    SyncThread1:81071
    SyncThread1:81072
    SyncThread1:81073
    SyncThread1:81074
    SyncThread1:.......

查看进程：

ZBMAC-f2b04ccbd:~ liuyazhou$ jps
    26144 Launcher
    95274 SynchronizedObject2
    45701
    26184 Jps
    ZBMAC-f2b04ccbd:~ liuyazhou$

ZBMAC-f2b04ccbd:~ liuyazhou$ jstack 95274
    2021-02-27 18:14:28
    Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.231-b11 mixed mode):
    
    "RMI Scheduler(0)" #18 daemon prio=9 os_prio=31 tid=0x00007fa021065800 nid=0x9e03 waiting on condition [0x00007000102c2000]
       java.lang.Thread.State: WAITING (parking)
    	at sun.misc.Unsafe.park(Native Method)
    	- parking to wait for  <0x00000006c000d6b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
    	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    	at java.lang.Thread.run(Thread.java:748)
    
    "RMI TCP Accept-0" #16 daemon prio=9 os_prio=31 tid=0x00007fa02106c800 nid=0xa203 runnable [0x00007000100bc000]
       java.lang.Thread.State: RUNNABLE
    	at java.net.PlainSocketImpl.socketAccept(Native Method)
    	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    	at java.net.ServerSocket.implAccept(ServerSocket.java:545)
    	at java.net.ServerSocket.accept(ServerSocket.java:513)
    	at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
    	at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
    	at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
    	at java.lang.Thread.run(Thread.java:748)
    
    "Attach Listener" #14 daemon prio=9 os_prio=31 tid=0x00007fa022832800 nid=0xa303 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "DestroyJavaVM" #13 prio=5 os_prio=31 tid=0x00007fa026809000 nid=0xf03 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "SyncThread2" #12 prio=5 os_prio=31 tid=0x00007fa026808000 nid=0x5803 waiting for monitor entry [0x000070000feb6000]
       java.lang.Thread.State: BLOCKED (on object monitor)
    	at SyncThread.method(SynchronizedObject2.java:20)
    	- waiting to lock <0x00000006c0012348> (a java.lang.Class for SyncThread)
    	at SyncThread.run(SynchronizedObject2.java:31)
    	- locked <0x00000006c00123b8> (a SyncThread)
    	at java.lang.Thread.run(Thread.java:748)
    
    "SyncThread1" #11 prio=5 os_prio=31 tid=0x00007fa0260a2000 nid=0xa603 waiting on condition [0x000070000fdb3000]
       java.lang.Thread.State: TIMED_WAITING (sleeping)
    	at java.lang.Thread.sleep(Native Method)
    	at SyncThread.method(SynchronizedObject2.java:23)
    	- locked <0x00000006c0012348> (a java.lang.Class for SyncThread)
    	at SyncThread.run(SynchronizedObject2.java:31)
    	- locked <0x00000006c0012dd0> (a SyncThread)
    	at java.lang.Thread.run(Thread.java:748)
    
    "Service Thread" #10 daemon prio=9 os_prio=31 tid=0x00007fa0260a1000 nid=0xa903 runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C1 CompilerThread3" #9 daemon prio=9 os_prio=31 tid=0x00007fa02380c000 nid=0x5503 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C2 CompilerThread2" #8 daemon prio=9 os_prio=31 tid=0x00007fa024802000 nid=0x3c03 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C2 CompilerThread1" #7 daemon prio=9 os_prio=31 tid=0x00007fa027002000 nid=0x3e03 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "C2 CompilerThread0" #6 daemon prio=9 os_prio=31 tid=0x00007fa02101f800 nid=0x3f03 waiting on condition [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "Monitor Ctrl-Break" #5 daemon prio=5 os_prio=31 tid=0x00007fa021846800 nid=0x3903 runnable [0x000070000f69e000]
       java.lang.Thread.State: RUNNABLE
    	at java.net.SocketInputStream.socketRead0(Native Method)
    	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    	at java.net.SocketInputStream.read(SocketInputStream.java:171)
    	at java.net.SocketInputStream.read(SocketInputStream.java:141)
    	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    	- locked <0x00000006c0023918> (a java.io.InputStreamReader)
    	at java.io.InputStreamReader.read(InputStreamReader.java:184)
    	at java.io.BufferedReader.fill(BufferedReader.java:161)
    	at java.io.BufferedReader.readLine(BufferedReader.java:324)
    	- locked <0x00000006c0023918> (a java.io.InputStreamReader)
    	at java.io.BufferedReader.readLine(BufferedReader.java:389)
    	at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)
    
    "Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fa02600e000 nid=0x3803 runnable [0x0000000000000000]
       java.lang.Thread.State: RUNNABLE
    
    "Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fa02101b800 nid=0x3103 in Object.wait() [0x000070000f392000]
       java.lang.Thread.State: WAITING (on object monitor)
    	at java.lang.Object.wait(Native Method)
    	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    	- locked <0x00000006c002d448> (a java.lang.ref.ReferenceQueue$Lock)
    	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
    
    "Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fa024801800 nid=0x4a03 in Object.wait() [0x000070000f28f000]
       java.lang.Thread.State: WAITING (on object monitor)
    	at java.lang.Object.wait(Native Method)
    	at java.lang.Object.wait(Object.java:502)
    	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    	- locked <0x00000006c0023af8> (a java.lang.ref.Reference$Lock)
    	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
    
    "VM Thread" os_prio=31 tid=0x00007fa022016800 nid=0x4b03 runnable 
    
    "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fa021001000 nid=0x1c07 runnable 
    
    "GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fa024800000 nid=0x2003 runnable 
    
    "GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fa021001800 nid=0x1d03 runnable 
    
    "GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fa024801000 nid=0x2a03 runnable 
    
    "GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fa025000000 nid=0x5303 runnable 
    
    "GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fa023800800 nid=0x5103 runnable 
    
    "GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fa021002800 nid=0x2b03 runnable 
    
    "GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fa021003000 nid=0x4f03 runnable 
    
    "GC task thread#8 (ParallelGC)" os_prio=31 tid=0x00007fa025800000 nid=0x2d03 runnable 
    
    "GC task thread#9 (ParallelGC)" os_prio=31 tid=0x00007fa024005800 nid=0x2e03 runnable 
    
    "VM Periodic Task Thread" os_prio=31 tid=0x00007fa022031800 nid=0xa703 waiting on condition 
    
    JNI global references: 231
    
    ZBMAC-f2b04ccbd:~ liuyazhou$

[Java线程状态转化][Java]

\-------------------------------------

我们使用jdk自带的jstack来分析。当linux出现cpu被java程序消耗过高时，以下过程说不定可以帮上你的忙：  
  
**1.top查找出哪个进程消耗的cpu高**  
21125 co\_ad2    18   0 1817m 776m 9712 S  3.3  4.9  12:03.24 java                                                                                            
5284 co\_ad     21   0 3028m 2.5g 9432 S  1.0 16.3   6629:44 java                                                                                            
21994 mysql     15   0  449m  88m 5072 S  1.0  0.6  67582:38 mysqld                                                                                          
8657 co\_sparr  19   0 2678m 892m 9220 S  0.3  5.7 103:06.13 java  
  
这里我们分析21125这个java进程。  
  
**2.top中shift+h查找出哪个线程消耗的cpu高**  
先输入top，然后再按shift+h  
21233 co\_ad2    15   0 1807m 630m 9492 S  1.3  4.0   0:05.12 java                                                                                            
20503 co\_ad2\_s  15   0 1360m 560m 9176 S  0.3  3.6   0:46.72 java                                                                                            
21134 co\_ad2    15   0 1807m 630m 9492 S  0.3  4.0   0:00.72 java                                                                                            
22673 co\_ad2    15   0 1807m 630m 9492 S  0.3  4.0   0:03.12 java  
  
这里我们分析21233这个线程，并且注意的是，这个线程是属于21125这个进程的。  
  
**3.jstack查找这个线程的信息**  
jstack \[进程\]|grep -A 10 \[线程的16进制\]  
即：

Java代码

1.  jstack 21125|grep -A 10 52f1

\-A 10表示查找到所在行的后10行。21233用计算器转换为16进制52f1，注意字母是小写。  
结果：

Java代码

1.  "http-8081-11" daemon prio=10 tid=0x00002aab049a1800 nid=0x52bb in Object.wait() \[0x0000000042c75000\]  
2.     java.lang.Thread.State: WAITING (on object monitor)  
3.       at java.lang.Object.wait(Native Method)  
4.       at java.lang.Object.wait(Object.java:485)  
5.       at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)

说不定可以一下子定位到出问题的代码。

参考

https://blog.csdn.net/T1DMzks/article/details/82719998

[https://www.iteye.com/topic/1114219][https_www.iteye.com_topic_1114219]

[Java]: https://mp.csdn.net/console/editor/html/82912031
[https_www.iteye.com_topic_1114219]: https://www.iteye.com/topic/1114219