Please Review (S): CR 6782663: Data produced by PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime is not accurate

[David Holmes - Sun Microsystems]

Hi John,

john cuthbertson - Sun Microsystems said the following on 07/16/09 04:47:
> * Do you have a specific idea in mind for the names of the new flags?

PrintApplicationExecutionTimes -> PrintInterSafepointIntervals
PrintApplicationStoppedTimes   -> PrintSafepointDurations

the key thing is to make sure the names reflect the actual measurements 
reported.

> * If I read your last paragraph correctly you are suggesting that in 
> jdk6 to support the old flag names (including the inaccurate reported 
> times) and the new flag names? Should the old flag name emit a warning 
> highlighting the new flag name? Should we disallow the old and new flags 
> both being set?

I suggest:

JDK6: if old names used, set old flags and print warning telling user 
that new flags exist and are 'better'
       if new names used, set new flags
       if both old and new names used, report user-is-confused error :)

JDK7: if old names used, set new flags and issue warning telling user 
old flags are no longer in use and to use new ones explicitly
       if new names used, set new flags
       if both old and new names used, report user-is-confused error

Of course, if there are CCC constraints then those must be followed.

Cheers,
David

> 
> Thanks,
> 
> JohnC
> 
> David Holmes - Sun Microsystems wrote:
>> Hi John,
>>
>> The problem with these flags and values is that the names (old or new) 
>> don't really tell you what exactly is being measured, and so noone 
>> really knows what they measure without going into the code in detail, 
>> and then they find that invariably they don't measure what the 
>> developer would like them to measure.
>>
>> I suspect these started as GC flags because they were measuring the 
>> duration of, and time between GC (safepoint) VM operations, and over 
>> time this morphed into measuring some aspect of the 
>> safepoint+vm-operation-execution code.
>>
>> As far as I can see from the current placement what is actually 
>> measured now is the safepoint duration:
>>
>> - from after the Threads_lock acquisition in SafepointSynchronize::begin
>> - to just before the Threads_lock release in SafepointSynchronize::end
>>
>> and the time between safepoints. So the flag names should reflect this 
>> directly. People should be able to correlate these values with those 
>> obtained from PrintSafepointStatistics.
>>
>> I think these are useful measures (even if the info can already be 
>> obtained from PrintSafepointStatistics) but I'm not sure that changing 
>> the behaviour of existing flags is a good thing to do to the user. I 
>> believe there are people out there that build up execution profiles of 
>> their apps based on what these flags report - even if the actual 
>> measurement is not ideal they can see how the measurements change 
>> across VM releases. Given this will end up in JDK7 and JDK6 I think it 
>> might be better to deprecate the old flags but leave them functioning 
>> as-is and add the news ones in addition. You might choose to support 
>> only the new ones in JDK7 while allowing JDK6 to use old or new.
>>
>> Cheers,
>> David Holmes
>>
>> john cuthbertson - Sun Microsystems said the following on 07/11/09 06:45:
>>> Hi Everyone,
>>>
>>> Can I have a couple of volunteers look over the attached changes for 
>>> this CR? The changes can be found at:
>>>
>>> http://cr.openjdk.java.net/~johnc/6782663/webrev.00/
>>>
>>> The issue here was that the code that was printing this information 
>>> was only executed for synchronous safepoints and ignored forced 
>>> safepoints. The user would see missing chunks of time (especially 
>>> with also displaying GC time stamps) giving the impression that the 
>>> JVM and app were idle. I was able to see this in the first few 
>>> minutes of SPECjbb2005.
>>>
>>> The simple solution was to move the printing into the routines that 
>>> record safepoint starts and ends, capturing guaranteed safepoints. I 
>>> have also changed the names of the flags to more accurately describe 
>>> that GCs are not the only things we take a safepoint for (and 
>>> deprecated the old flag names).
>>>
>>> With these changes I see a delta between (application time + 
>>> safepoint time) and the GC timestamp of around 0.1s instead of around 
>>> 5 and 7 seconds previously.
>>>
>>> Testing: SPECjbb2005 (exhibited behavior), IBM UK's own evaluation, 
>>> and JPRT.
>>>
>>> Thanks,
>>>
>>> JohnC
>