RFR: 8234742: Improve handshake logging

[Patricio Chilano]

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