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

[David Holmes - Sun Microsystems]

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