RFR(L): 8219436: Safepoint logs correction and misc

[Robbin Ehn]

Hi Martin,

On 2019-02-20 16:18, Doerr, Martin wrote:
> Hi Robbin,
> 
> thanks for updating the comments in safepoint.cpp and the condition for which threads print a timeout message.
> 
> It should work fine with the following minor fix for -XX:+SafepointTimeout in safepoint.cpp:
> -    safepoint_limit_time = SafepointTracing::start_of_safepoint() + (jlong)SafepointTimeoutDelay * (MILLIUNITS / NANOUNITS);
> +    safepoint_limit_time = SafepointTracing::start_of_safepoint() + (jlong)SafepointTimeoutDelay * (NANOUNITS / MILLIUNITS);

Thanks, fixed!

> 
> Logging looks good to me, but it should also get reviewed by somebody who is more familiar with it.

Thanks, Robbin!

> 
> Best regards,
> Martin
> 
> 
> -----Original Message-----
> From: Robbin Ehn <robbin.ehn at oracle.com>
> Sent: Mittwoch, 20. Februar 2019 10:34
> To: hotspot-runtime-dev at openjdk.java.net
> Cc: Doerr, Martin <martin.doerr at sap.com>
> Subject: RFR(L): 8219436: Safepoint logs correction and misc
> 
> Hi all,
> 
> Issue:
> https://bugs.openjdk.java.net/browse/JDK-8219436
> 
> Changeset:
> http://cr.openjdk.java.net/~rehn/8219436/v01/webrev/
> 
> Safepoint logs takes multiple time-stamps for same measurement but different
> logs. The most meaningful logs is not under just safepoint tag.
> The sync phase ignored some potential time-consuming parts, joing GC-threads
> with STS-joiner and grabbing the Threads_lock, which is now included in 'sync'.
> "Reaching safepoint" is sync + cleanup.
> 
> Also 'unused' JFR event removed and SafepointTimeout was not working proper.
> 
> "-Xlog:safepoint" now gives you only:
> [2.045s][info][safepoint] Safepoint "Cleanup", Time since last: 34559 ns,
> Reaching safepoint: 307612 ns, At safepoint: 26194 ns, Total: 333806 ns
> [2.046s][info][safepoint] Safepoint "RevokeBias", Time since last: 99207 ns,
> Reaching safepoint: 319601 ns, At safepoint: 168210 ns, Total: 487811 ns
> 
> "-Xlog:safepoint+stats" now gives you this updated table:
> [1.308s][info][safepoint,stats] VM Operation                 [ threads: total
> initial_running ][ time:       sync    cleanup       vmop      total ]
> page_trap_count
> [1.308s][info][safepoint,stats] Cleanup                      [              9
>              1 ][          2175486     233869      20660    2430015 ]               0
> [1.602s][info][safepoint,stats] Deoptimize                   [             14
>              0 ][            30698     289306     168425     488429 ]               0
> [1.605s][info][safepoint,stats] Deoptimize                   [             14
>              0 ][            22789      68223     156759     247771 ]               0
> [1.917s][info][safepoint,stats] EnableBiasedLocking          [             19
>              0 ][            40133     651166     561768    1253067 ]               0
> 
> With the usual exits logs:
> [2.286s][info][safepoint,stats] Cleanup                              1
> [2.286s][info][safepoint,stats] Deoptimize                           2
> [2.286s][info][safepoint,stats] G1CollectForAllocation               1
> [2.286s][info][safepoint,stats] EnableBiasedLocking                  1
> [2.286s][info][safepoint,stats] RevokeBias                          12
> [2.286s][info][safepoint,stats] Exit                                 1
> [2.286s][info][safepoint,stats] VM operations coalesced during safepoint 32
> [2.286s][info][safepoint,stats] Maximum sync time  2175486 ns
> [2.286s][info][safepoint,stats] Maximum vm operation time (except for Exit VM
> operation)  88697164 ns
> 
> "-Xlog:safepoint+stats" and "-Xlog:safepoint" use the same timestamp, so if you
> have both logs enabled they add up.
> 
> Thanks, Robbin
>