RFR: 8234742: Improve handshake logging

[Robbin Ehn]

Hi Per,

On 2019-11-26 15:24, Per Liden wrote:
> Hi,
> 
> I just realized that my comment on "8234796: Refactor Handshake::execute to take 
> a HandshakeOperation" is probably more relevant for this change, so 
> cut-n-pasting it here:

I think the other issue was correct.

Thanks, Robbin

> 
> 
> I kind of think HandshakeOperation is exposing a too wide API here. I'm thinking 
> the following things doesn't quite belong in there, but is more Handshake 
> internal stuff.
> 
>    void do_handshake(JavaThread* thread);
>    bool thread_has_completed() { return _done.trywait(); }
>    bool executed() const { return _executed; }
> 
> #ifdef ASSERT
>    void check_state() {
>      assert(!_done.trywait(), "Must be zero");
>    }
> #endif
> 
> How about you just expose a closure that inherits from ThreadClosure, but also 
> takes a name? Like this:
> 
> class HandshakeClosure : public ThreadClosure {
> private:
>    const char* const _name;
> 
> public:
>    HandshakeClosure(const char* name) :
>        _name(name) {}
> 
>    const char* name() const {
>      return _name;
>    }
> 
>    virtual void do_thread(Thread* thread) = 0;
> };
> 
> That way we expose a narrower API, and it also helps avoid the need for 
> HandshakeOperation -> ThreadClosure wrappers. The other stuff can stay internal 
> in a wrapping HandshakeThreadOperation like it did before.
> 
> What do you think?
> 
> /Per
> 
> 
> On 11/26/19 2: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/
>>
>> 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