Bug ID: JDK-8234742 Improve handshake logging

Type: Enhancement
Component: hotspot
Sub-Component: runtime
Affected Version: 14

Priority: P4
Status: Resolved
Resolution: Fixed

Submitted: 2019-11-25
Updated: 2020-12-30
Resolved: 2019-12-04

JDK 11	JDK 14
11.0.11-oracleFixed	14 b26Fixed

Now that several sub-systems use handshakes it is important to have good logging to get an understanding what's going on.
Without turn on a lot of loggning there is no way to determine what the handshake did.
Let's fix that!

Fix Request Should get backported for parity with 11.0.11-oracle. Doesn't apply cleanly at all, mainly because JDK-8244340 was integrated with adaptations before this one (wrong order). Review thread: http://mail.openjdk.java.net/pipermail/jdk-updates-dev/2020-December/004525.html
23-12-2020
URL: https://hg.openjdk.java.net/jdk/jdk/rev/c2ce3849c62f User: rehn Date: 2019-12-04 11:01:32 +0000
04-12-2019
Examples: -Xlog:handshake,safepoint [7.148s][info][safepoint] Safepoint "ZMarkStart", Time since last: 381873579 ns, Reaching safepoint: 451132 ns, At safepoint: 491202 ns, Total: 942334 ns [7.151s][info][handshake] Handshake "ZMarkFlushAndFreeStacks", Targeted threads: 25, Executed by targeted threads: 8, Total completion time: 46884 ns [7.151s][info][handshake] Handshake "ZMarkFlushAndFreeStacks", Targeted threads: 25, Executed by targeted threads: 10, Total completion time: 94547 ns [7.152s][info][handshake] Handshake "ZMarkFlushAndFreeStacks", Targeted threads: 25, Executed by targeted threads: 10, Total completion time: 33545 ns [7.154s][info][safepoint] Safepoint "ZMarkEnd", Time since last: 4697901 ns, Reaching safepoint: 218800 ns, At safepoint: 1462059 ns, Total: 1680859 ns [7.156s][info][handshake] Handshake "ZRendezvous", Targeted threads: 25, Executed by targeted threads: 10, Total completion time: 37291 ns [7.157s][info][safepoint] Safepoint "ZVerify", Time since last: 2201206 ns, Reaching safepoint: 295463 ns, At safepoint: 928077 ns, Total: 1223540 ns [7.161s][info][safepoint] Safepoint "ZRelocateStart", Time since last: 3161645 ns, Reaching safepoint: 206278 ns, At safepoint: 357284 ns, Total: 563562 ns [8.162s][info][safepoint] Safepoint "Cleanup", Time since last: 1000123769 ns, Reaching safepoint: 526489 ns, At safepoint: 23345 ns, Total: 549834 ns [8.182s][info][handshake] Handshake "RevokeOneBias", Targeted threads: 1, Executed by targeted threads: 0, Total completion time: 41322 ns -Xlog:handshake*=trace [1.259s][trace][handshake ] Threads signaled, begin processing blocked threads by VMThtread [1.259s][trace][handshake ] Processing handshake by VMThtread [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f2594022800, is_vm_thread: true, completed in 487 ns [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f259459e000, is_vm_thread: false, completed in 1233 ns [1.259s][trace][handshake ] Processing handshake by VMThtread [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f25945a0000, is_vm_thread: false, completed in 669 ns [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f259428a800, is_vm_thread: true, completed in 462 ns [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f25945b3800, is_vm_thread: false, completed in 574 ns ... [1.259s][trace][handshake ] Processing handshake by VMThtread [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f25945b6000, is_vm_thread: true, completed in 100 ns [1.259s][trace][handshake ] Processing handshake by VMThtread [1.259s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f25945b7800, is_vm_thread: true, completed in 103 ns [1.260s][info ][handshake ] Handshake "ZRendezvous", Targeted threads: 28, Executed by targeted threads: 4, Total completion time: 629534 ns [1.260s][debug][handshake,task ] Operation: ZRendezvous for thread 0x00007f25945a3800, is_vm_thread: false, completed in 608 ns
25-11-2019
http://cr.openjdk.java.net/~rehn/8234742/full/webrev/
25-11-2019