PrintGCApplicationConcurrentTime / PrintGCApplicationStoppedTime

Jon Masamitsu Jon.Masamitsu at Sun.COM
Thu Apr 16 15:39:01 UTC 2009



On 04/16/09 08:06, Rainer Jung wrote:
> 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.

I don't think there will be an order of magnitude increase over
what outputs today.  In the experiments I did the most common
application-stop/application-run lines had to do with GC and
biased locking.  The additional lines will be for periodic
safepoints to do asynchronous VM operations (operations requested
but not needed synchonously).  Those are at most at 1 second
intervals.  If you have biased locking turned off and long
periods between GC's, these safepoints for asynchronous VM
operations could dominate but I think you will have to accept
that cost to get the benefit.

> 
> 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.

The stop times due to GC and other VM operations are straight forward.
The application run time between VM operations will take work and
may be confusing.  We're considering special casing GC since that's
of common interest (i.e., adding up all the application run times
between two GC's to print the total application run time between the
those GC's).

> 
> 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.



More information about the hotspot-gc-dev mailing list