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

[Doerr, Martin]

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);

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

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