RFR: 8234742: Improve handshake logging

Robbin Ehn robbin.ehn at oracle.com
Mon Nov 25 16:33:03 UTC 2019


Hi all, please review.

There is little useful information in the handshaking logs.
This changes the handshakes logs similar to safepoint logs, so the basic need of
what handshake operation and how long it took easily can be tracked.
Also the per thread log is a bit enhanced.

The refactoring using HandshakeOperation instead of a ThreadClosure is not
merely for this change. Other changes in the pipeline also require a more
complex HandshakeOperation.

Issue:
https://bugs.openjdk.java.net/browse/JDK-8234742
Changeset:
http://cr.openjdk.java.net/~rehn/8234742/full/webrev/

Passes t1-3.

Thanks, Robbin

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


More information about the hotspot-dev mailing list