RFR: 8234742: Improve handshake logging

[David Holmes]

Hi Robbin,

Updates all seem fine.

Thanks,
David

On 28/11/2019 1:51 am, Robbin Ehn wrote:
> Hi David, thanks for having a look!
> 
> On 11/27/19 4:25 AM, David Holmes wrote:
>> Hi Robbin,
>>
>> On 26/11/2019 11:06 pm, Robbin Ehn wrote:
>>> Hi,
>>>
>>> Here is the logging part separately:
>>> http://cr.openjdk.java.net/~rehn/8234742/v2/full/webrev/index.html
>>>
>>> It contains one additional change from the first version:
>>>       if (number_of_threads_issued < 1) {
>>> -      log_debug(handshake)("No threads to handshake.");
>>> +      log_handshake_info(start_time_ns, _op->name(), 0, 0, " (no 
>>> threads)");
>>>         return;
>>>       }
>>>
>>> Passes t1-3.
>>>
>>> So this goes on top of 8234796:
>>> http://cr.openjdk.java.net/~rehn/8234796/full/webrev/
>>
>> src/hotspot/share/runtime/handshake.hpp
>>
>> I was surprised that "process_by_vmthread" doesn't really mean that. 
>> Perhaps rename to try_process_by_vmThread?
> 
> I did, but also renamed:
> bool handshake_process_by_vmthread() in thread.hpp
> 
>>
>> ---
>>
>> src/hotspot/share/runtime/handshake.cpp
>>
>> 91     log_info(handshake)("Handshake \"%s\", Targeted threads: %d, 
>> Executed by targeted threads: %d, Total completion time: " 
>> JLONG_FORMAT " ns%s",
>>
>> Probably better to end with " ns, %s" so you don't have to remember to 
>> start the 'extra' string with a space each time.
> 
> Fixed, but I didn't like the ending "," when the string was empty, so I 
> did a
> different fix!
> 
>>
>> 168     log_trace(handshake)("Threads signaled, begin processing 
>> blocked threads by VMThtread")
>>
>> Existing typo: VMThtread
> 
> Fixed!
> 
>>
>> Otherwise seems okay.
>>
> 
> 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