RFR: 8234742: Improve handshake logging

[Robbin Ehn]

Thanks Patricio!

/Robbin

On 2019-12-03 18:52, Patricio Chilano wrote:
> Hi Robbin,
>
> v3 looks good to me!
>
> Patricio
> On 11/27/19 10:51 AM, Robbin Ehn wrote:
>> v3 which is also rebased on latest 8234796:
>> Inc:
>> http://cr.openjdk.java.net/~rehn/8234742/v3/inc/webrev/index.html
>> Full:
>> http://cr.openjdk.java.net/~rehn/8234742/v3/full/webrev/index.html
>>
>> t1-3
>>
>> Thanks, Robbin
>>
>>> Thanks,
>>> David
>>> -----
>>>
>>>> Thanks, Robbin
>>>>
>>>> On 11/25/19 5:33 PM, 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.
>>>>>
>>>>> 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
>