RFR: 8234742: Improve handshake logging

[Robbin Ehn]

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