37 jstack 的输出结果分析

Posted 2022-07-30 蓝风9

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了37 jstack 的输出结果分析相关的知识，希望对你有一定的参考价值。

前言

之前看到过这样的几篇帖子

dump 中 waiting on condition、parking to wait for 应该怎么理解

为什么jstack dump 出来的线程的线程为什么都是000结尾的。

是关于 jstack 的输出结果的意义

之前是记录了 todo, 需要整理一下

呵呵了解这个对于一些简单的 vm 调试还是很有帮助的

测试用例

package com.hx.test07;

import com.hx.test04.Test18DoubleCheckSingleton;
import sun.misc.Unsafe;

import java.util.concurrent.locks.LockSupport;

/**
 * JStackLog
 *
 * @author Jerry.X.He <970655147@qq.com>
 * @version 1.0
 * @date 2020-07-05 11:10
 */
public class Test08JStackLog 

  // Test08JStackLog
  public static void main(String[] args) 

    Object lock = new Object();
    Unsafe unsafe = Test18DoubleCheckSingleton.getUnsafe();

    new Thread("sleepThread") 
      @Override
      public void run() 
        synchronized (lock) 
          try 
            Thread.sleep(1000 * 1000);
           catch (Exception e) 
            e.printStackTrace();
          
        
      
    .start();

    new Thread("waitThread") 
      @Override
      public void run() 
        synchronized (lock) 
          try 
            lock.wait();
           catch (Exception e) 
            e.printStackTrace();
          
        
      
    .start();


    new Thread("parkThread") 
      @Override
      public void run() 
        LockSupport.park(lock);
      
    .start();

    new Thread("parkThread02") 
      @Override
      public void run() 
        LockSupport.park();
      
    .start();

    new Thread("runnableThread") 
      @Override
      public void run() 
        int i = 0;
        while (true) 
          i++;
        
      
    .start();

jstack 查看 Test08JStackLog 的栈帧信息

"runnableThread" #17 prio=5 os_prio=31 tid=0x00007f809a8bb000 nid=0x9603 runnable [0x00007000092a8000]
   java.lang.Thread.State: RUNNABLE
	at com.hx.test07.Test08JStackLog$6.run(Test08JStackLog.java:97)

"parkThread" #16 prio=5 os_prio=31 tid=0x00007f809c000800 nid=0x6d03 waiting on condition [0x00007000091a5000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base/Native Method)
	at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:323)
	at com.hx.test07.Test08JStackLog$5.run(Test08JStackLog.java:88)

"parkThreadLockObj" #15 prio=5 os_prio=31 tid=0x00007f809a8b9800 nid=0x6c03 waiting on condition [0x00007000090a2000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base/Native Method)
	- parking to wait for  <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)
	at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:194)
	at com.hx.test07.Test08JStackLog$4.run(Test08JStackLog.java:81)

"waitThreadInQueue" #14 prio=5 os_prio=31 tid=0x00007f8099025800 nid=0x6b03 waiting for monitor entry [0x0000700008f9f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.hx.test07.Test08JStackLog$3.run(Test08JStackLog.java:69)
	- waiting to lock <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

"sleepThread" #13 prio=5 os_prio=31 tid=0x00007f8099850800 nid=0x9903 waiting on condition [0x0000700008e9c000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(java.base/Native Method)
	at com.hx.test07.Test08JStackLog$2.run(Test08JStackLog.java:55)
	- locked <0x00000007bfbc2b80> (a com.hx.test07.Test08JStackLog)
	- locked <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

"waitThreadAcquired" #12 prio=5 os_prio=31 tid=0x00007f809a8b8800 nid=0x6903 in Object.wait() [0x0000700008d99000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base/Native Method)
	- waiting on <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)
	at java.lang.Object.wait(java.base/Object.java:516)
	at com.hx.test07.Test08JStackLog$1.run(Test08JStackLog.java:41)
	- waiting to re-lock in wait() <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

这里面的内容主要是分为了两个部分, 一个是线程部分的信息

另外一个是当前线程的栈帧部分的信息

线程的信息

我们关注的几个线程信息如下

"runnableThread" #17 prio=5 os_prio=31 tid=0x00007f809a8bb000 nid=0x9603 runnable [0x00007000092a8000]
   java.lang.Thread.State: RUNNABLE

"parkThread" #16 prio=5 os_prio=31 tid=0x00007f809c000800 nid=0x6d03 waiting on condition [0x00007000091a5000]
   java.lang.Thread.State: WAITING (parking)

"parkThreadLockObj" #15 prio=5 os_prio=31 tid=0x00007f809a8b9800 nid=0x6c03 waiting on condition [0x00007000090a2000]
   java.lang.Thread.State: WAITING (parking)

"waitThreadInQueue" #14 prio=5 os_prio=31 tid=0x00007f8099025800 nid=0x6b03 waiting for monitor entry [0x0000700008f9f000]
   java.lang.Thread.State: BLOCKED (on object monitor)

"sleepThread" #13 prio=5 os_prio=31 tid=0x00007f8099850800 nid=0x9903 waiting on condition [0x0000700008e9c000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)

"waitThreadAcquired" #12 prio=5 os_prio=31 tid=0x00007f809a8b8800 nid=0x6903 in Object.wait() [0x0000700008d99000]
   java.lang.Thread.State: WAITING (on object monitor)

以 runnableThread 为例, 下图输出了线程的名称, threadId, priority, last_java_sp(mask 掉了最右边的12个bit), java线程的状态

上图中的 Thread::print_on 输出了线程的 native_priority, tid(threadOop 对应的 JavaThread 的地址), os线程的状态

线程的栈帧信息

"runnableThread" #17 prio=5 os_prio=31 tid=0x00007f809a8bb000 nid=0x9603 runnable [0x00007000092a8000]
   java.lang.Thread.State: RUNNABLE
	at com.hx.test07.Test08JStackLog$6.run(Test08JStackLog.java:97)

"parkThread" #16 prio=5 os_prio=31 tid=0x00007f809c000800 nid=0x6d03 waiting on condition [0x00007000091a5000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base/Native Method)
	at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:323)
	at com.hx.test07.Test08JStackLog$5.run(Test08JStackLog.java:88)

"parkThreadLockObj" #15 prio=5 os_prio=31 tid=0x00007f809a8b9800 nid=0x6c03 waiting on condition [0x00007000090a2000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base/Native Method)
	- parking to wait for  <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)
	at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:194)
	at com.hx.test07.Test08JStackLog$4.run(Test08JStackLog.java:81)

"waitThreadAcquired" #12 prio=5 os_prio=31 tid=0x00007f809a8b8800 nid=0x6903 in Object.wait() [0x0000700008d99000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base/Native Method)
	- waiting on <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)
	at java.lang.Object.wait(java.base/Object.java:516)
	at com.hx.test07.Test08JStackLog$1.run(Test08JStackLog.java:41)
	- waiting to re-lock in wait() <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

"waitThreadInQueue" #14 prio=5 os_prio=31 tid=0x00007f8099025800 nid=0x6b03 waiting for monitor entry [0x0000700008f9f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.hx.test07.Test08JStackLog$3.run(Test08JStackLog.java:69)
	- waiting to lock <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

"sleepThread" #13 prio=5 os_prio=31 tid=0x00007f8099850800 nid=0x9903 waiting on condition [0x0000700008e9c000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(java.base/Native Method)
	at com.hx.test07.Test08JStackLog$2.run(Test08JStackLog.java:55)
	- locked <0x00000007bfbc2b80> (a com.hx.test07.Test08JStackLog)
	- locked <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)

然后我们再来看一下这两个对象的信息, 0x00000007bfbc2af8 是 lock 对象, 0x00000007bfbc2b80 是 lock02 对象

com.hx.test07.Test08JStackLog 
0x00000007bfbc2af8 - klass: 'com/hx/test07/Test08JStackLog'
 - ---- fields (total size 5 words):
 - 'f01' 'I' @12  0
 - 'f02' 'I' @16  0
 - 'f03' 'I' @20  0
 - 'f04' 'I' @24  0
 - 'f05' 'I' @28  0
 - private 'identStr' 'Ljava/lang/String;' @32  "lock"0x00000007bfbc2b20 (f7f78564 0)
com.hx.test07.Test08JStackLog 
0x00000007bfbc2b80 - klass: 'com/hx/test07/Test08JStackLog'
 - ---- fields (total size 5 words):
 - 'f01' 'I' @12  0
 - 'f02' 'I' @16  0
 - 'f03' 'I' @20  0
 - 'f04' 'I' @24  0
 - 'f05' 'I' @28  0
 - private 'identStr' 'Ljava/lang/String;' @32  "lock02"0x00000007bfbc2ba8 (f7f78575 0)

再来看一下 Thread 打印栈帧信息的相关代码

打印锁的相关信息代码如下

runnableThread 打印出了栈帧信息, 没有锁的相关信息

parkThread 打印出了栈帧信息, 没有锁的相关信息

parkThreadLockObj 的当前栈帧, 存在 currentParkBlocker, 该对象是 lock, 其他的栈帧没有锁的相关信息

waitThreadAcquired 的当前栈帧, 是 lock.wait, 记录了当前栈帧, 以及 wait on 哪一个对象, 父级栈帧, 获取了 lock 的锁, 但是 wait 释放了, wait 结束之后还需要重新获取 lock 的锁, 标记的是 "waiting to re-lock in wait() <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)"

waitThreadInQueue 的当前栈帧是在等待获取 lock 的锁, 因为 lock 的锁被 sleepThread 获取了, 所以标记的是 "waiting to lock <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)"

sleepThread 的当前栈帧调用是 Thread.sleep 方法, 父级栈帧是线程的 run 方法, 并且获取了 lock, lock02 的锁, 因此标记的是 "locked <0x00000007bfbc2b80> (a com.hx.test07.Test08JStackLog)", "locked <0x00000007bfbc2af8> (a com.hx.test07.Test08JStackLog)"

完

参考

dump 中 waiting on condition、parking to wait for 应该怎么理解

为什么jstack dump 出来的线程的线程为什么都是000结尾的。

以上是关于37 jstack 的输出结果分析的主要内容，如果未能解决你的问题，请参考以下文章

java中虚拟机命令：jstack使用方法