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

Tue Apr 24 15:08:52 PDT 2012

Hi,

One correction to my original post.

To collect a metric representing the overall "allocation rate" of our
application, I should be summing the ParNew deltas, not the "overall
heap" deltas from the gc log.

The "overall heap" delta will reflect the amount collected from ParNew.
However, the ParNew delta will also include the volume of objects
promoted to tenured gen.

This is a more accurate (albeit delayed) representation of allocation
volume, since we don't care how objects leave the new gen - by being
collected or by being promoted.
If it left the new gen by promotion, it was briefly before allocated,
and thus should contribute to the reported allocation volume.

Cheers,
-tt

On Mon, Apr 23, 2012 at 10:51 PM, Srinivas Ramakrishna
<ysr1729 at gmail.com> wrote:
> Yes, that's right.
>
> By the way, a few years ago, John had posted an awk script on this alias
> that did this for you.
> I recently had occasion to need to use it, and found it gave a few problems
> with the jdk 6 logs i
> was processing, so I fixed a few bugs in it and extended it to summarize and
> plot other metrics
> of interest to me. I am happy to share my modifications to John;s script
> here and on
> the OpenJDK PrintGCStats project page later this week.
>
> -- ramki
>
>
> On Mon, Apr 23, 2012 at 1:03 PM, Taras Tielkes <taras.tielkes at gmail.com>
> wrote:
>>
>> 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
>> >
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>