Re: [RFC] Enhanced Garbage Collection Probe Points

[Jon VanAlten <jvanalte@redhat.com>]

----- Original Message -----
> From: "Lukas Berk" <lberk@redhat.com>
> To: distro-pkg-dev@openjdk.java.net
> Cc: systemtap@sourceware.org
> Sent: Wednesday, August 22, 2012 4:33:09 PM
> Subject: Re: [RFC] Enhanced Garbage Collection Probe Points
> 
> Hey list,
> 
> I've updated and attached my patch to reflect the comments made in
> the thread above, primarily:
> 
> - split begin and end probe points where possible
> 
> - correct probe point names
> 
> - include and autoconf version of the tapset for immediate inclusion
> 

Definite improvements!

There's some nit's I'd like to see addressed.  Mostly consistency and
clarity in comments/documentation.  Details:

We have a hotspot.stp, a hotspot_jni.stp; maybe this one should be
hotspot_gc.stp?

Adding this fluff to the existing systemtap.patch, may not be the
best way.  As I understand it, Mark is trying to get the existing
stuff upstream.  Combining this into same IcedTea patch may make
it more difficult if/when this upstreaming is eventually successful
and needs to be removed from IcedTea.  I'd suggest introducing a
separate patch to the icedtea sources.

+ * @size: word size to be cleaned

(in several places)
This wording (pun not intended) is not entirely clear.  Playing the
ignorant reader, I am not sure if this means the wordsize that the
jvm uses, or the total space, in words, that will be collected on
this gc run.  Can this be clarified?

+ * @is_full: If TRUE, attempt a full collection of the generation

And if not TRUE?  (again playing the ignorant reader).

+ * Description: This marks the end of a parallel collection of a new 
+ * generation.
+ * This is different than a gc_collect_parallel generation due to it being
+ * specifically defined as a parNewGeneration

The 'clarification' sentence reads to me like "Y is not X because it
is Y".  I'd consider leaving it off, or providing a better explanation.

+ * Description: The start of a newly defined generation collection

The previous probes' documentation says "This marks the...", I'd love
to see consistency in the wording.

+ * Description: This is the start of a collection of a tenured generation
+ * (a geneartion that has survived multiple garbage collections and is 

Here too, also typo "generation"

+ * probe - gc_collect_parallel_scavenge
+ * 
+ * @name: gc_collect_parallel_scavenge
+ * @address: address of object being collected
+ * @cause: cause of the collection
+ * 
+ * Description: This is a parallel collection, where the jvm process don't
+ * have to halt while the gc is being completed

I want to make sure I understand this.  If I read this correctly, this
probe fires many times between a begin and end of parallel gc run, for
each object that is scavenged?  If I do understand this, then saying
"this is a parallel collection" I think is the wrong wording.  This
is not a collection, but an event that is part of a collection run.  If
I misunderstand, please clarify :)

+ * Description: A delete statement of an obeject

Typo "obeject"

Otherwise, I don't really have any concerns with this.  I hope though
that Mark (who introduced the systemtap support for the existing
probes) could also take a look for sanity.  I've added him to CC
directly, even though he probably also gets this through the list.

> I've also run the DaCapo benchmarking suite[1] and have attached the
> results below.
> 
> In order to properly judge the performance effects (if any) my probe
> points have had on hotspot, I ran three different sets of tests
> (using the eclipse benchmark).  First, with icedtea configured using
> --disable-systemtap, then configured with systemtap and no probes
> run, and finally with the gc probes in use with a basic log(probestr)
> systemtap script. (ie $stap -ve 'probe hotspot.gc_* {log(probestr)}'
> -c "java -jar dacapo-9.12-bach.jar eclise -n 10". I ran each test 4
> times to get a better sample size.
> 
> --disable-systemtap:
> run 1: 44119 msec
> run 2: 43255 msec
> run 3: 44517 msec
> run 4: 44017 msec
> --------------------
> avg: 43977 msec
> 
> --enable-systemtap but not used:
> run 1: 44987 msec
> run 2: 47154 msec
> run 3: 48099 msec
> run 4: 41069 msec
> --------------------
> avg: 45327 msec
> 
> --enable-systemtap and used:
> run 1: 47538 msec
> run 2: 43264 msec
> run 3: 40396 msec
> run 4: 44422 msec
> --------------------
> avg: 43905 msec
> 
> Considering that the probe points seem to have relatively little
> impact
> on the benchmarking results and the interest in my patch, 

I think there's more to look at in terms of performance.  However,
despite what the numbers here show, from my understanding (Mark,
please chime in here!) the existence of these probes in the source
should in theory not affect runtime performance.  Otherwise, I might
be asking to see data for --enable-systemtap w/o this patch as well
to compare really what this patch adds.  Anyhow, unless I am quite
wrong about this, I don't think there is any performance concern
for adding these probes, only for when they are used.  So, consider
my next paragraph not for this patch, but more generally to discuss
performance impact of using these probes.

These numbers do seem to raise some questions, though.  Why do we
see such variation between the runs?  I'd encourage you to explore
this further.  Another aspect to consider: looking at run time of
benchmark will show the impact aggregated over entire java process,
but it would be interesting to see the impact relative to time
actually spent in gc.  I'd be concerned if simply printing this
probestr at beginning and end of gc made the gc run last 10% longer,
even if it looks relatively minor aggregated over full java process
run time.  I'm not sure how you'd go about trying to measure this,
however.

> what else
> needs to be done to get this patch applied to icedtea?
> 

Well, I am basically OK with this aside from the things mentioned
above.  I guess remaining still is the question of testing these.  I
wouldn't block this based on lacking tests (the previous probes went
untested for ages before I added tests), but I also don't want this
to go in without a plan to eventually add tests; when we did add
tests for the other probes, we actually found regressions and even
things that had never properly worked iirc.

Have you given any thought to how you might add tests for these
probes to the existing set of probe tests?

cheers,
jon