RFR: 8283147: Include NonJavaThread stacktrace during thread dump

Wed Mar 16 02:46:56 UTC 2022

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 at 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 at 11.0.11/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base at 11.0.11/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base at 11.0.11/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base at 11.0.11/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base at 11.0.11/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base at 11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base at 11.0.11/ThreadPoolExecutor.java:628)
	at java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base at 11.0.11/Executors.java:668)
	at java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base at 11.0.11/Executors.java:665)
	at java.security.AccessController.doPrivileged(java.base at 11.0.11/Native Method)
	at java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(java.base at 11.0.11/Executors.java:665)
	at java.lang.Thread.run(java.base at 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 at 19-internal/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base at 19-internal/Reference.java:253)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base at 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 at 19-internal/Native Method)
	- waiting on <0x00000000a00027c0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base at 19-internal/ReferenceQueue.java:155)
	- locked <0x00000000a00027c0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base at 19-internal/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base at 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 at 19-internal/Native Method)
	- waiting on <0x00000000a010aba8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base at 19-internal/ReferenceQueue.java:155)
	- locked <0x00000000a010aba8> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base at 19-internal/CleanerImpl.java:140)
	at java.lang.Thread.run(java.base at 19-internal/Thread.java:828)
	at jdk.internal.misc.InnocuousThread.run(java.base at 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 at 19-internal/Native Method)
	- waiting on <0x00000000a01ff400> (a java.util.TaskQueue)
	at java.util.TimerThread.mainLoop(java.base at 19-internal/Timer.java:563)
	- locked <0x00000000a01ff400> (a java.util.TaskQueue)
	at java.util.TimerThread.run(java.base at 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 at 19-internal/Native Method)
	- waiting on <0x00000000a01ffa98> (a java.util.TaskQueue)
	at java.util.TimerThread.mainLoop(java.base at 19-internal/Timer.java:563)
	- locked <0x00000000a01ffa98> (a java.util.TaskQueue)
	at java.util.TimerThread.run(java.base at 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 at 19-internal/Native Method)
	at sun.nio.ch.EPollSelectorImpl.doSelect(java.base at 19-internal/EPollSelectorImpl.java:118)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base at 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 at 19-internal/SelectorImpl.java:141)
	at sun.net.httpserver.ServerImpl$Dispatcher.run(jdk.httpserver at 19-internal/ServerImpl.java:373)
	at java.lang.Thread.run(java.base at 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