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

[Robbin Ehn]

Hi Coleen,

On 2019-02-20 20:44, coleen.phillimore at oracle.com wrote:
> 
> This does look good, but I was wondering if the calculations 
> NANOUNITS/MILLIUNITS should be in the SafepointTracing function, or in another 
> that returns ms

Thanks,

> 
> http://cr.openjdk.java.net/~rehn/8219436/v01/webrev/src/hotspot/share/runtime/tieredThresholdPolicy.cpp.udiff.html 
> 
> 
> + jlong delta_s = t - SafepointTracing::end_of_last_safepoint() / (NANOUNITS / 
> MILLIUNITS);
> 
> 
> instead
> 
> + jlong delta_s = t - SafepointTracing::end_of_last_safepoint_ms();
> 
> http://cr.openjdk.java.net/~rehn/8219436/v01/webrev/src/hotspot/share/runtime/vmThread.cpp.udiff.html 
> 
> 
> Here too:
> 
> + long interval_ms = SafepointTracing::time_since_last_safepoint() / (NANOUNITS 
> / MILLIUNITS);
> 
> 
> This is minor suggestion.  I'm glad you updated the safepoint logging to be what 
> is most useful for working on this code, and removed it from runtimeService.

I tried to keep everything in ns for sanity. But sure, I'll change to XX_ms.

Thanks, Robbin

> 
> Thanks!
> Coleen
> 
> 
> On 2/20/19 2:14 PM, Robbin Ehn wrote:
>> 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
>>>
>