When we use jcmd <pid> Thread.dump/jstack <pid>, we could dump all Java thread
stack trace, but unfortunately we are not able to print NonJavaThread stack
trace such as VMThread/GCWorker, etc. For these threads, we know nothing about
what are they doing/are they blocked in pthread condition from jstack output.
An alternative is to use pstack, it internally attaches destination process and
uses `thread apply all bt`, which introduces more overhead and much more
dangerous.
====== JStack Ouput(Currrent)
...
"ApplicationImpl pooled thread 441" #1478 prio=4 os_prio=31 cpu=11.71ms
elapsed=60.30s tid=0x00007f8d32171000 nid=0x22f23 waiting on condition
[0x0000700010d5d000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
- parking to wait for <0x00000007af851760> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at
java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
at
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.11/SynchronousQueue.java:462)
at
java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.11/SynchronousQueue.java:361)
at
java.util.concurrent.SynchronousQueue.poll(java.base@11.0.11/SynchronousQueue.java:937)
at
java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1053)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
at
java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base@11.0.11/Executors.java:668)
at
java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base@11.0.11/Executors.java:665)
at java.security.AccessController.doPrivileged(java.base@11.0.11/Native
Method)
at
java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(java.base@11.0.11/Executors.java:665)
at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)
"VM Thread" os_prio=31 cpu=31205.83ms elapsed=154131.15s tid=0x00007f8d49046000
nid=0x4703 runnable
"GC Thread#0" os_prio=31 cpu=3811.96ms elapsed=154131.18s
tid=0x00007f8d49809800 nid=0x3603 runnable
"GC Thread#1" os_prio=31 cpu=3749.09ms elapsed=154130.24s
tid=0x00007f8d4a9b3000 nid=0x6103 runnable
"GC Thread#2" os_prio=31 cpu=3745.73ms elapsed=154129.74s
tid=0x00007f8d48249000 nid=0x12f27 runnable
"GC Thread#3" os_prio=31 cpu=3692.77ms elapsed=154129.74s
tid=0x00007f8d48b93000 nid=0xe50b runnable
"GC Thread#4" os_prio=31 cpu=3728.57ms elapsed=154129.74s
tid=0x00007f8d47b0b000 nid=0xe603 runnable
"GC Thread#5" os_prio=31 cpu=3726.08ms elapsed=154129.74s
tid=0x00007f8d47afc800 nid=0xe803 runnable
"GC Thread#6" os_prio=31 cpu=3660.35ms elapsed=154129.02s
tid=0x00007f8d48de5800 nid=0x15d2f runnable
"GC Thread#7" os_prio=31 cpu=3676.68ms elapsed=154129.02s
tid=0x00007f8d48dc4800 nid=0x16103 runnable
"GC Thread#8" os_prio=31 cpu=3676.15ms elapsed=154128.31s
tid=0x00007f8d4849d800 nid=0x1f503 runnable
"GC Thread#9" os_prio=31 cpu=3570.95ms elapsed=154128.31s
tid=0x00007f8d494ab000 nid=0x1f303 runnable
"CMS Main Thread" os_prio=31 cpu=6715.33ms elapsed=154131.18s
tid=0x00007f8d4780f800 nid=0x4b03 runnable
"CMS Thread#0" os_prio=31 cpu=2429.86ms elapsed=154131.18s
tid=0x00007f8d4900e000 nid=0x3703 runnable
"CMS Thread#1" os_prio=31 cpu=2422.35ms elapsed=154129.72s
tid=0x00007f8d4d044000 nid=0x11a03 runnable
"CMS Thread#2" os_prio=31 cpu=2418.81ms elapsed=154129.72s
tid=0x00007f8d48b93800 nid=0xea03 runnable
"VM Periodic Task Thread" os_prio=31 cpu=10658.80ms elapsed=154130.41s
tid=0x00007f8d49035000 nid=0xa003 waiting on condition
JNI global refs: 660, weak refs: 1217
Most of above information makes no sense for further debugging. I think we can
extend this functionality, e.g. add a new flag such as DumpAllThreadStackTrace,
to print non java thread stack trace:
====== JStack Ouput(Modified)
2022-03-16 10:33:49
Full thread dump OpenJDK 64-Bit Server VM (19-internal-adhoc.qingfengyy.jdktip
mixed mode, sharing):
Threads class SMR info:
_java_thread_list=0x00007fc0900015f0, length=15, elements={
0x00007fc1281babd0, 0x00007fc1281bc190, 0x00007fc1281c21e0, 0x00007fc1281c36b0,
0x00007fc1281c4bc0, 0x00007fc1281c6740, 0x00007fc1281c7dc0, 0x00007fc1281c9340,
0x00007fc1281f8a70, 0x00007fc128209120, 0x00007fc12823ea50, 0x00007fc12823fb80,
0x00007fc128246f20, 0x00007fc1280255c0, 0x00007fc090000be0
}
"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.11ms elapsed=12.11s
tid=0x00007fc1281babd0 nid=91395 waiting on condition [0x00007fc0b6877000]
java.lang.Thread.State: RUNNABLE
at
java.lang.ref.Reference.waitForReferencePendingList(java.base@19-internal/Native
Method)
at
java.lang.ref.Reference.processPendingReferences(java.base@19-internal/Reference.java:253)
at
java.lang.ref.Reference$ReferenceHandler.run(java.base@19-internal/Reference.java:215)
"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.31ms elapsed=12.11s
tid=0x00007fc1281bc190 nid=91396 in Object.wait() [0x00007fc0b6776000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@19-internal/Native Method)
- waiting on <0x00000000a00027c0> (a java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@19-internal/ReferenceQueue.java:155)
- locked <0x00000000a00027c0> (a java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@19-internal/ReferenceQueue.java:176)
at
java.lang.ref.Finalizer$FinalizerThread.run(java.base@19-internal/Finalizer.java:183)
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=12.10s
tid=0x00007fc1281c21e0 nid=91397 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.07ms elapsed=12.10s
tid=0x00007fc1281c36b0 nid=91398 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=0.17ms elapsed=12.10s
tid=0x00007fc1281c4bc0 nid=91399 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=19.05ms elapsed=12.10s
tid=0x00007fc1281c6740 nid=91400 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C1 CompilerThread0" #19 daemon prio=9 os_prio=0 cpu=38.05ms elapsed=12.10s
tid=0x00007fc1281c7dc0 nid=91401 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"Sweeper thread" #25 daemon prio=9 os_prio=0 cpu=0.04ms elapsed=12.10s
tid=0x00007fc1281c9340 nid=91402 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Notification Thread" #26 daemon prio=9 os_prio=0 cpu=0.06ms elapsed=12.09s
tid=0x00007fc1281f8a70 nid=91409 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Common-Cleaner" #27 daemon prio=8 os_prio=0 cpu=0.12ms elapsed=12.08s
tid=0x00007fc128209120 nid=91413 in Object.wait() [0x00007fc0b5948000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@19-internal/Native Method)
- waiting on <0x00000000a010aba8> (a java.lang.ref.ReferenceQueue$Lock)
at
java.lang.ref.ReferenceQueue.remove(java.base@19-internal/ReferenceQueue.java:155)
- locked <0x00000000a010aba8> (a java.lang.ref.ReferenceQueue$Lock)
at
jdk.internal.ref.CleanerImpl.run(java.base@19-internal/CleanerImpl.java:140)
at java.lang.Thread.run(java.base@19-internal/Thread.java:828)
at
jdk.internal.misc.InnocuousThread.run(java.base@19-internal/InnocuousThread.java:162)
"server-timer" #28 daemon prio=5 os_prio=0 cpu=0.23ms elapsed=12.03s
tid=0x00007fc12823ea50 nid=91418 in Object.wait() [0x00007fc0b5847000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@19-internal/Native Method)
- waiting on <0x00000000a01ff400> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(java.base@19-internal/Timer.java:563)
- locked <0x00000000a01ff400> (a java.util.TaskQueue)
at java.util.TimerThread.run(java.base@19-internal/Timer.java:516)
"server-timer1" #29 daemon prio=5 os_prio=0 cpu=0.81ms elapsed=12.03s
tid=0x00007fc12823fb80 nid=91419 in Object.wait() [0x00007fc0b5746000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@19-internal/Native Method)
- waiting on <0x00000000a01ffa98> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(java.base@19-internal/Timer.java:563)
- locked <0x00000000a01ffa98> (a java.util.TaskQueue)
at java.util.TimerThread.run(java.base@19-internal/Timer.java:516)
"HTTP-Dispatcher" #30 prio=5 os_prio=0 cpu=0.98ms elapsed=12.02s
tid=0x00007fc128246f20 nid=91421 runnable [0x00007fc0b5645000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPoll.wait(java.base@19-internal/Native Method)
at
sun.nio.ch.EPollSelectorImpl.doSelect(java.base@19-internal/EPollSelectorImpl.java:118)
at
sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@19-internal/SelectorImpl.java:129)
- locked <0x00000000a01fc928> (a sun.nio.ch.Util$2)
- locked <0x00000000a01fc598> (a sun.nio.ch.EPollSelectorImpl)
at
sun.nio.ch.SelectorImpl.select(java.base@19-internal/SelectorImpl.java:141)
at
sun.net.httpserver.ServerImpl$Dispatcher.run(jdk.httpserver@19-internal/ServerImpl.java:373)
at java.lang.Thread.run(java.base@19-internal/Thread.java:828)
"DestroyJavaVM" #31 prio=5 os_prio=0 cpu=108.15ms elapsed=12.01s
tid=0x00007fc1280255c0 nid=91386 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" #32 daemon prio=9 os_prio=0 cpu=0.18ms elapsed=0.10s
tid=0x00007fc090000be0 nid=91781 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"VM Thread" os_prio=0 cpu=0.63ms elapsed=12.11s tid=0x00007fc1281b7900
nid=91394 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"GC Thread#0" os_prio=0 cpu=0.11ms elapsed=12.12s tid=0x00007fc128066a20
nid=91387 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xf4a977] WorkerThreads::threads_do(ThreadClosure*) const+0x37
V [libjvm.so+0x70cf16] G1CollectedHeap::gc_threads_do(ThreadClosure*)
const+0x16
V [libjvm.so+0xe98624] Threads::print_on(outputStream*, bool, bool, bool,
bool)+0x4a4
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"G1 Main Marker" os_prio=0 cpu=0.03ms elapsed=12.12s tid=0x00007fc128076ee0
nid=91388 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x70cf26] G1CollectedHeap::gc_threads_do(ThreadClosure*)
const+0x26
V [libjvm.so+0xe98624] Threads::print_on(outputStream*, bool, bool, bool,
bool)+0x4a4
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"G1 Conc#0" os_prio=0 cpu=0.02ms elapsed=12.12s tid=0x00007fc128077f60
nid=91389 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xf4a977] WorkerThreads::threads_do(ThreadClosure*) const+0x37
V [libjvm.so+0x70cf35] G1CollectedHeap::gc_threads_do(ThreadClosure*)
const+0x35
V [libjvm.so+0xe98624] Threads::print_on(outputStream*, bool, bool, bool,
bool)+0x4a4
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"G1 Refine#0" os_prio=0 cpu=0.03ms elapsed=12.13s tid=0x00007fc1281881e0
nid=91390 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x7275c8] G1ConcurrentRefine::threads_do(ThreadClosure*)+0x78
V [libjvm.so+0x70cf44] G1CollectedHeap::gc_threads_do(ThreadClosure*)
const+0x44
V [libjvm.so+0xe98624] Threads::print_on(outputStream*, bool, bool, bool,
bool)+0x4a4
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"G1 Service" os_prio=0 cpu=0.71ms elapsed=12.13s tid=0x00007fc1281892a0
nid=91391 runnable
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xe98624] Threads::print_on(outputStream*, bool, bool, bool,
bool)+0x4a4
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
"VM Periodic Task Thread" os_prio=0 cpu=2.22ms elapsed=12.10s
tid=0x00007fc1281fa560 nid=91410 waiting on condition
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xf21da5] VM_PrintThreads::doit()+0x25
V [libjvm.so+0xf2248a] VM_Operation::evaluate()+0xea
V [libjvm.so+0xf23df8] VMThread::evaluate_operation(VM_Operation*)+0xb8
V [libjvm.so+0xf244a7] VMThread::inner_execute(VM_Operation*)+0x3a7
V [libjvm.so+0xf24757] VMThread::run()+0xb7
V [libjvm.so+0xe99680] Thread::call_run()+0xc0
V [libjvm.so+0xc379f8] thread_native_entry(Thread*)+0xd8
JNI global refs: 28, weak refs: 0
-------------
Commit messages:
- 8283147: Include NonJavaThread stacktrace during thread dump
Changes: https://git.openjdk.java.net/jdk/pull/7833/files
Webrev: https://webrevs.openjdk.java.net/?repo=jdk&pr=7833&range=00
Issue: https://bugs.openjdk.java.net/browse/JDK-8283147
Stats: 46 lines in 4 files changed: 39 ins; 6 del; 1 mod
Patch: https://git.openjdk.java.net/jdk/pull/7833.diff
Fetch: git fetch https://git.openjdk.java.net/jdk pull/7833/head:pull/7833
PR: https://git.openjdk.java.net/jdk/pull/7833
