PrintGCApplicationConcurrentTime / PrintGCApplicationStoppedTime

[Nicolas Michael]

Hi Jon,

we have been using PrintGCApplicationConcurrentTime and 
PrintGCApplicationStoppedTime to figure out what was going on when one 
of our processes was blocked for up to 100 seconds around GC's, although 
GC's only lasted a few hundred ms. It turned out that it sometimes took 
100+ seconds to bring all threads to a safepoint. I currently don't 
remember the bug id, but Ramki probably does. (It's been fixed for 1 or 
2 years, now.) For this it's been very useful. Since it includes 
safepointing time (for GC's), PrintGCApplicationStoppedTime would always 
be >= the reported GC pause times (which might be confusing if you don't 
know what PrintGCApplicationStoppedTime is counting -- but if you want 
to see the GC time, you can look at the GC outputs instead of the 
StoppedTime ... So that's ok for me!).

Other than that we don't use PrintGCApplicationConcurrentTime and 
PrintGCApplicationStoppedTime too often. We didn't have problems with 
other safepoints yet, but if we had (or just to make sure we *don't* 
have), it would be nice to get some information about the time our 
mutator threads are blocked, not only due to GC. So reducing the 
reported times to just those due to GC would mean losing some maybe 
valuable information (unless you introduce new parameters that count 
everything again).

Since I don't really know what other safepoints you have that are not 
due to "VM operations" and that are not reported right now, I'm not sure 
whether I would want to have them in the logs as well every time they 
occur (depending on how often they occur)... But actually I would prefer 
to have *all* time due to safepointing reported somehow. In case there 
is some problem with safepointing, it would be good to have some 
counters showing that. Or just to see how much time the application is 
*really* running (vs. being blocked). Reporting all this with 
PrintGCApplicationStoppedTime and PrintGCApplicationConcurrentTime (and 
probably drop the "GC" in the name) sounds good to me!

Nick.

Jon Masamitsu schrieb:
> Question: Do users care about applications times output
> for PrintGCApplicationConcurrentTime only relative to
> GC's?
> 
> 
> I have a CR
> 
> 6782663: Data produced by PrintGCApplicationConcurrentTime and 
> PrintGCApplicationStoppedTime is not accurate
> 
> where the complaint is that the application time as output
> for PrintGCApplicationConcurrentTime does not match the time
> as measured by the time between GC timestamps.  Actually the
> user is adding up all the times reported for
> PrintGCApplicationConcurrentTime between the GC timestamps
> and saying that that sum can be vastly off from the
> time between GC timestamps.  And the user is right.
> 
> I think the problem is that the timers used to report
> PrintGCApplicationConcurrentTime are updated more often
> than the PrintGCApplicationConcurrentTime time is
> reported.  In VMThread::loop() in share/vm/runtime/vmThread.cpp
> around line 425 the PrintGCApplicationConcurrentTime is
> reported before the call to SafepointSynchronize::begin().
> Whereas near line 391 and near line 520 calls to
> SafepointSynchronize::begin() do not report for
> PrintGCApplicationConcurrentTime.  The calls to
> SafepointSynchronize::begin() will update the application
> timer (_app_timer via a call to
> RuntimeService::record_safepoint_begin()).  Updating
> resets the timer to the current time and the
> PrintGCApplicationConcurrentTime output is then the
> time since the last safepoint (not since the application
> restarted after the last GC).
> 
> So anyone know why the PrintGCApplicationConcurrentTime output
> does not print for all safepoints?  Should it only printout
> when a VM operation is executed as it does now?
> 
> If yes, should the spelling of
> PrintGCApplicationConcurrentTime be changed to drop
> the GC, PrintApplicationConcurrentTime.  Similarly with
> PrintGCApplicationStoppedTime -> PrintApplicationStoppedTime.
> 
> Or should it printout for all safepoints?  This is
> simpler in that the printing could be added to
> RuntimeService::record_safepoint_begin()) so
> we would not miss new safepoints.  But we might
> be dumping useless information.
> 
> Or I could hack the code so that information is only
> printed around GC's.  And maybe not printout some
> useful information.
> 
> 
>