PrintGCApplicationConcurrentTime / PrintGCApplicationStoppedTime

[Rainer Jung]

On 16.04.2009 15:48, Jon Masamitsu wrote:
> Sentiment at this point seems to favor including
> the application times (stopped time and run time)
> for all the safepoints.  We'll start on making that
> the fix.

I would also agree, but with the additional remark, that in case this
increases the number of output lines (number of events per time that
trigger a line) very much (like by a factor of 10), then it might be not
that nice.

If it would be allowed w.r.t. compatibility to include some keyword
indicating the cause/type of the event on the same line, that would make
it even more useful. GC could be one such event type.

Regards,

Rainer

> On 04/14/09 11:14, Jon Masamitsu wrote:
>> 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.