RFR: 8234742: Improve handshake logging

[Robbin Ehn]

Hi David,

On 11/26/19 1:38 AM, David Holmes wrote:
> 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.
>

Sure

Thanks, Robbin

> 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