jstack排查锁竞争

2022-01-11 05:52:04

排查线程信息的常用工具是jstack，jstack用于生成当前进程的所有线程快照。

准备

设计一个程序：两个线程，两个锁，互相等待造成死锁。

然后使用jstack排查锁竞争情况。

jstack使用

一般出现cpu异常的情况下，会使用top命令找到cpu占用较高的进程，得到进程pid。

如果定位到或怀疑是某个java进程出现锁竞争，可以直接使用jps找到对应的pid，进行一下操作。

jstack查看线程信息

jstack -pid

jstack 18176
2021-06-08 09:51:39
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.31-b07 mixed mode):

"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x0000000002f36000 nid=0x41f4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-1" #13 prio=5 os_prio=0 tid=0x000000001f26f000 nid=0x4724 waiting for monitor entry [0x000000002012f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at clc.jvm.Student1.run(AuLock.java:60)
        - waiting to lock <0x000000076b9dd3f0> (a java.lang.String)
        - locked <0x000000076b584598> (a java.lang.Integer)

"Thread-0" #12 prio=5 os_prio=0 tid=0x000000001f1c1000 nid=0x2acc waiting for monitor entry [0x000000002002f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at clc.jvm.Student1.run(AuLock.java:50)
        - waiting to lock <0x000000076b584598> (a java.lang.Integer)
        - locked <0x000000076b9dd3f0> (a java.lang.String)

"Service Thread" #11 daemon prio=9 os_prio=0 tid=0x000000001f124000 nid=0x45cc runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread3" #10 daemon prio=9 os_prio=2 tid=0x000000001f0a7000 nid=0x46d0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x000000001f092000 nid=0x160c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #8 daemon prio=9 os_prio=2 tid=0x000000001ee29000 nid=0x1438 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 tid=0x000000001f06c800 nid=0x384c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Ctrl-Break" #6 daemon prio=5 os_prio=0 tid=0x000000001ed90000 nid=0x4b3c runnable [0x000000001f92e000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:150)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        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 <0x000000076baa2810> (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 <0x000000076baa2810> (a java.io.InputStreamReader)
        at java.io.BufferedReader.readLine(BufferedReader.java:389)
        at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:48)

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000001ea6b800 nid=0x4050 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

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

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000000302d000 nid=0x3a48 in Object.wait() [0x000000001ea2e000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076b5062f8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
        - locked <0x000000076b5062f8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000003026000 nid=0x1d28 in Object.wait() [0x000000001e92f000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076b505d68> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
        - locked <0x000000076b505d68> (a java.lang.ref.Reference$Lock)

"VM Thread" os_prio=2 tid=0x000000001ca38800 nid=0x424c runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002f4c000 nid=0x2720 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002f4d800 nid=0xab0 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000002f4f000 nid=0x2c34 runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000002f50800 nid=0x19b8 runnable

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x0000000002f53000 nid=0x496c runnable

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000002f54000 nid=0x1080 runnable

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x0000000002f58000 nid=0x2ed4 runnable

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x0000000002f59800 nid=0x47d8 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x000000001f125000 nid=0x1244 waiting on condition

JNI global references: 17


Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x0000000003029f68 (object 0x000000076b9dd3f0, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x000000000302c958 (object 0x000000076b584598, a java.lang.Integer),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at clc.jvm.Student1.run(AuLock.java:60)
        - waiting to lock <0x000000076b9dd3f0> (a java.lang.String)
        - locked <0x000000076b584598> (a java.lang.Integer)
"Thread-0":
        at clc.jvm.Student1.run(AuLock.java:50)
        - waiting to lock <0x000000076b584598> (a java.lang.Integer)
        - locked <0x000000076b9dd3f0> (a java.lang.String)

Found 1 deadlock.

以上为jstack详情，由于程序比较简单，所以线程信息比较短。

jstack内容分析
死锁问题排查

由于程序出现明显的死锁，jstack直接将问题抛出：Found 1 deadlock.

并且找到出现的线程：

"Thread-1":

at clc.jvm.Student1.run(AuLock.java:60)

- waiting to lock <0x000000076b9dd3f0> (a java.lang.String)

- locked <0x000000076b584598> (a java.lang.Integer)

"Thread-0":

at clc.jvm.Student1.run(AuLock.java:50)

- waiting to lock <0x000000076b584598> (a java.lang.Integer)

- locked <0x000000076b9dd3f0> (a java.lang.String)

<0x000000076b9dd3f0> <>中的十六进制数 表示一个锁的唯一标识，相同的地址表示为同一把锁。

这段显示:

  1. Thread-1已经锁定了<0x000000076b584598>，但是在等待<0x000000076b9dd3f0>；
  2. Thread-0已经锁定了<0x000000076b9dd3f0>，但是在等待<0x000000076b584598>

因此这两个线程构成了死锁。

还能得到信息：两个线程的方法分别是at clc.jvm.Student1.run(AuLock.java:60)和 at clc.jvm.Student1.run(AuLock.java:50)；

这些信息就可以定位程序中死锁的产生位置了。

其他信息

查看线程运行状态：
java.lang.Thread.State: BLOCKED (on object monitor)

java.lang.Thread.State 会显示此线程的运行状态

  • NEW,未启动的。不会出现在Dump中。
  • RUNNABLE,在虚拟机内执行的。
  • BLOCKED,受阻塞并等待监视器锁。
  • WATING,无限期等待另一个线程执行特定操作。
  • TIMED_WATING,有时限的等待另一个线程的特定操作。
  • TERMINATED,已退出的。

常见的修饰符信息：

  • locked <地址> 目标：使用synchronized申请对象锁成功,监视器的拥有者。
  • waiting to lock <地址> 目标：使用synchronized申请对象锁未成功,在迚入区等待。
  • waiting on <地址> 目标：使用synchronized申请对象锁成功后,释放锁幵在等待区等待。
  • parking to wait for <地址> 目标

jstack排查锁竞争

上一篇：1.0，可以打开网页


下一篇：开发一个js包并且发布到npmjs.com上