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

[Krystal Mok]

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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120423/1972a8f3/attachment.html