Two basic questions on -verbosegc and -XX:+PrintTenuringDistribution

[Taras Tielkes]

Hi,

Sorry to return this thread to the original question :-)
The additional data from jstat -snap is indeed quite useful.

However, I think the totals easily harvested from the gc logs are
accurate enough for my purposes, which is measuring overall allocation
rate, and overall promotion rate.
Performing a few manual calculations shows that the promotion volume I
calculate as the differentce of ParNew delta and total heap delta is
reasonably close to the "tenuring age 15" age group from the preceding
ParNew.
I just want to make sure I'm not missing something obvious here. The
assumption is of course that PermGen is quite stable, and that
promotion and CMS failures are relatively rate.

Thanks,
-tt

On Mon, Apr 23, 2012 at 9:28 PM, Kobe Bryant <kbbryant61 at gmail.com> wrote:
> sorry for interjecting myself into this interesting conversation:
>
>   > There's a PerfData counter that keeps track of the promoted size (in
> bytes) in a minor GC.
>   >You could use jstat to fetch the value of that counter, like this:
>
> does this give me the number of promoted bytes in the last minor gc? so if I
> have to track promotion volumes
> at each gc I have to keep polling this metric (and even then I might miss an
> update and lose information, since
> this info is not cumulative), correct?
>
> Also, is there a similar metric to track size harvested from tenured space
> at each full GC?
>
> thank you
>
> /K
>
> On Sun, Apr 22, 2012 at 7:40 PM, Krystal Mok <rednaxelafx at gmail.com> wrote:
>>
>> Hi Taras,
>>
>>> d) When looking at -XX:+PrintTenuringDistribution output, I assume the
>>> distribution reflects the situation *after* the enclosing ParNew event
>>> in the log.
>>
>>
>> That's right. The stats are actually printed after the collection has
>> completed.
>>
>> FYI, to get accurate promotion size info, you don't always have to parse
>> the GC log. There's a PerfData counter that keeps track of the promoted size
>> (in bytes) in a minor GC. You could use jstat to fetch the value of that
>> counter, like this:
>>
>> $ jstat -J-Djstat.showUnsupported=true -snap `pgrep java` | grep
>> sun.gc.policy.promoted=
>> sun.gc.policy.promoted=680475760
>>
>> There are a couple of other counters that can be played in conjuntion,
>> e.g. sun.gc.collector.0.invocations, which shows the number of minor GCs:
>>
>> $ jstat -J-Djstat.showUnsupported=true -snap `pgrep java` | grep
>> sun.gc.collector.0.invocations=
>> sun.gc.collector.0.invocations=23
>>
>> - Kris
>>
>>
>> On Mon, Apr 23, 2012 at 4:24 AM, Taras Tielkes <taras.tielkes at gmail.com>
>> wrote:
>>>
>>> Hi,
>>>
>>> We're using a time-series database to store and aggregate monitoring
>>> data from our systems, including GC behavior.
>>>
>>> I'm thinking of adding two metrics:
>>> * total allocation (in K per minute)
>>> * total promotion (in K per minute)
>>>
>>> The gc logs are the source for this data, and I'd like to verify that
>>> my understanding of the numbers is correct.
>>>
>>> Here's an example verbosegc line of output (we're running ParNew+CMS):
>>> [GC 2136581.585: [ParNew:345951K->40960K(368640K), 0.0676780 secs]
>>> 3608692K->3323692K(5201920K), 0.0680220 secs]
>>>
>>> a) The delta between the ParNew "before" and "after" is:
>>> 345951K-40960K=304991K
>>> My understanding is that the 304991K is the total of (collected in
>>> young gen + promoted to tenured gen)
>>> Since this number of composed of two things, it's not directly useful by
>>> itself.
>>>
>>> b) The delta between the overall heap "before" and "after" is:
>>> 3608692K-3323692K=285000K
>>> I assume that this is effectively the volume that was collected in
>>> this ParNew cycle.
>>> Would it be correct to calculate the total allocation rate of the
>>> running application (in a given period) from summing the total heap
>>> deltas (in a given timespan)?
>>>
>>> I do realize that it's a "collected kilobytes" metric, but I think
>>> it's close enough to be used as a "delayed" allocation number,
>>> especially when looking at a timescale of 10 minutes or more.
>>> It has the additional convenience of requiring to parse the current
>>> gc.log line only, and not needing to correlate with the preceding
>>> ParNew event.
>>>
>>> c) I take it that the difference between the two deltas (ParNew delta
>>> and total heap delta) is effectively the promotion volume?
>>> In the example above, this would give a promotion volume of
>>> (345951K-40960K)-(3608692K-3323692K)=19991K
>>>
>>> d) When looking at -XX:+PrintTenuringDistribution output, I assume the
>>> distribution reflects the situation *after* the enclosing ParNew event
>>> in the log.
>>>
>>> Thanks in advance for any corrections,
>>> -tt
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>