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

[coleen.phillimore at oracle.com]

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

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.

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