RFR: 8234742: Improve handshake logging

[David Holmes]

Hi Robbin,

On 26/11/2019 2:33 am, Robbin Ehn wrote:
> 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.

This change seems to be predominantly about the refactoring and only 
touches the logging in a few places. I think this either needs to be 
split into two issues or the focus of the issue changed so that it is 
predominantly about the refactor and only incidentally improves the logging.

Thanks,
David
-----

> 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