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

[Doerr, Martin]

Hi Robbin,

ok. No problem.

Another question:
Was it intended to remove the timeout check in vmThread.cpp (2nd usage of VMThread::no_op_safepoint(false))?
If so, you could remove the bool parameter check_time. It's no longer used. Would be ok for me.

Best regards,
Martin


-----Original Message-----
From: Robbin Ehn <robbin.ehn at oracle.com> 
Sent: Donnerstag, 21. Februar 2019 10:48
To: Doerr, Martin <martin.doerr at sap.com>; hotspot-runtime-dev at openjdk.java.net
Subject: Re: RFR(L): 8219436: Safepoint logs correction and misc

Hi Martin,

I notice that just after I had sent RFR, so updated in-place, you most have 
picked up the changeset before my update, sorry about that.

  890       ls.print_cr("# SafepointSynchronize::begin: Threads which did not 
reach the safepoint:");
  891       for (JavaThreadIteratorWithHandle jtiwh; JavaThread *cur_thread = 
jtiwh.next(); ) {

Thanks, Robbin

On 2019-02-21 10:06, Doerr, Martin wrote:
> Hi Robbin,
> 
> please also fix the Windows build warning:
> safepoint.cpp(891): warning C4101: 'cur_state': unreferenced local variable
> 
> Thanks,
> Martin
> 
> 
> -----Original Message-----
> From: Robbin Ehn <robbin.ehn at oracle.com>
> Sent: Mittwoch, 20. Februar 2019 20:15
> To: Doerr, Martin <martin.doerr at sap.com>; hotspot-runtime-dev at openjdk.java.net
> Subject: Re: RFR(L): 8219436: Safepoint logs correction and misc
> 
> 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
>>