排查JVM的线程卡死

发表于 | 分类于 ， ，

Thread Status

  • NEW
  • RUNNABLE
  • BLOCKED
  • WAITING
  • TIMED_WAITING
  • TERMINATED

Practice - jstack

1
2
3
4
5
6
7
8
jstack -l pid

# 强制打印堆栈信息到标准输出，如果使用 jstack PID 没有响应的情况下(此时 JVM 进程可能挂起)，加 -F 参数
jstack -F pid

# -heap 参数用于查看指定 JVM 进程的堆的信息，包括堆的各个参数的值，堆中新生代、年老代的内存大小、使用率等
jmap -heap PID
jmap -F -heap PID

-l：long listing. Prints additional information about locks

此时输出的日志如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
2019-06-15 08:51:29
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.192-b12 mixed mode):

"Disruptor-1" #31 prio=10 os_prio=0 tid=0x00007f3fad4d2800 nid=0x39 runnable [0x00007f3ece5fa000]
   java.lang.Thread.State: RUNNABLE
	at com.lmax.disruptor.BusySpinWaitStrategy.waitFor(BusySpinWaitStrategy.java:39)
	at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:56)
	at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:159)
	at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"main/queue-thread-local-cleaner-daemon" #29 daemon prio=5 os_prio=0 tid=0x00007f3fad4be000 nid=0x38 runnable [0x00007f3ee41f8000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007b145e200> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	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)

   Locked ownable synchronizers:
	- None

"chronicle-weak-reference-cleaner" #28 daemon prio=5 os_prio=0 tid=0x00007f3fad476800 nid=0x37 in Object.wait() [0x00007f3ee42f9000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000007b1fd3910> (a java.lang.ref.ReferenceQueue$Lock)
	at net.openhft.chronicle.core.util.WeakReferenceCleaner$ReferenceProcessor.run(WeakReferenceCleaner.java:101)
	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)

   Locked ownable synchronizers:
	- <0x00000007b1fe43f0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"MyPerf4J-BackgroundExecutor_0" #17 prio=5 os_prio=0 tid=0x00007f3f04002800 nid=0x2d waiting on condition [0x00007f3f1d3bc000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000004d52001f8> (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.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	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)

   Locked ownable synchronizers:
	- None

"MyPerf4J-LightWeightScheduler-1" #9 prio=5 os_prio=0 tid=0x00007f3f00001000 nid=0x26 waiting on condition [0x00007f3f1e4f6000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000004d5200bf0> (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:1088)
	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)

   Locked ownable synchronizers:
	- None

"MyPerf4J-LightWeightScheduler-0" #8 prio=5 os_prio=0 tid=0x00007f3face7c800 nid=0x25 runnable [0x00007f3f1e5f7000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000004d5200bf0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
	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)

   Locked ownable synchronizers:
	- None
	
"Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x00007f3facdca000 nid=0x23 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f3facd97800 nid=0x22 in Object.wait() [0x00007f3f1ec1e000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000004d52012d0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000004d52012d0> (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)

   Locked ownable synchronizers:
	- None

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

   Locked ownable synchronizers:
	- None

"main" #1 prio=5 os_prio=0 tid=0x00007f3fac00c000 nid=0x9 runnable [0x00007f3fb1fb2000]
   java.lang.Thread.State: RUNNABLE
	at com.anda.trading.Application.blockingUntilJournalFinish(Application.kt:188)
	at com.anda.trading.Application.readJournalFromHeader(Application.kt:180)
	at com.anda.trading.Application.readJournal(Application.kt:217)
	at com.anda.trading.ApplicationKt.main(Application.kt:567)
	at com.anda.trading.ApplicationKt.main(Application.kt)

   Locked ownable synchronizers:
	- None

异常日志

1
2
3
4
5
6
7
8
9
10
"main" #1 prio=5 os_prio=0 tid=0x00007f3fac00c000 nid=0x9 runnable [0x00007f3fb1fb2000]
   java.lang.Thread.State: RUNNABLE
	at com.anda.trading.Application.blockingUntilJournalFinish(Application.kt:188)
	at com.anda.trading.Application.readJournalFromHeader(Application.kt:180)
	at com.anda.trading.Application.readJournal(Application.kt:217)
	at com.anda.trading.ApplicationKt.main(Application.kt:567)
	at com.anda.trading.ApplicationKt.main(Application.kt)

   Locked ownable synchronizers:
	- None

问题点：at com.anda.trading.Application.blockingUntilJournalFinish(Application.kt:188) 死循环等待。

Practice - arthas

Reference