Home
Reading
Searching
Subscribe
Sponsors
Statistics
Posting
Contact
Spam
Lists
Links
About
Hosting
Filtering
Features Download
Marketing
Archives
FAQ
Blog
 
Gmane
From: John Coomes <John.Coomes-xsfywfwIY+M <at> public.gmane.org>
Subject: Re: Is there any GC log reader?
Newsgroups: gmane.comp.java.openjdk.hotspot.gc.devel
Date: Friday 20th April 2007 21:19:40 UTC (over 10 years ago)
Neo Jia ([email protected]) wrote:
> On 4/19/07, John Coomes <[email protected]> wrote:
> > Neo Jia ([email protected]) wrote:
> > > hi,
> > >
> > > Are there any scripts to read and parse the GC log dumped out by
> > > PrintHeapAtGC?
> >
> > Hi Neo,
> >
> > I don't know of anything that parses the output from
> > -XX:+PrintHeapAtGC.  However, I currently maintain an aging awk script
> > that parses the output from -XX:+PrintGCDetails and produces
> > statistics (min, avg, stddev) for gc pauses, heap sizes, etc.  If
> > you'd like a copy, let me know.
> 
> John,
> 
> I would like to get a copy of your script. ...

Hi Neo,

I've attached three awk scripts:  PrintGCFixup, PrintGCStats and
CompareGCStats.  Here's a brief write-up on each:

PrintGCFixup

Cleans up certain types of GC output to make analysis more
accurate. This is not always necessary, but is generally a good
idea. The main things it cleans up are the output from

    * -XX:+PrintVMOptions (enabled by default in debug builds)
    * -XX:+TraceClassUnloading (enabled by PrintGCDetails, and which
obscures Full GC output)
    * -XX:+PrintHeapAtGC (which obscures almost everything prior to 1.6.0)
    * -XX:+PrintTenuringDistribution
    * -XX:+PrintParallelOldGCPhaseTimes (specific to parallel compaction)

One thing to note is that it still has a hard time with the output
from both -XX:+PrintHeapAtGC and -XX:+PrintTenuringDistribution,
particularly with releases prior to 1.6.0. If this bites you, please
submit a patch :-).

The comments at the top have a bit more info.

PrintGCStats

Scans GC logs and prints statistics about GC and allocation. Works
best if the logs were created with -XX:+PrintGCDetails and
-XX:+PrintGCTimeStamps. Also has some basic support for creating data
files for plotting w/gnuplot or StarOffice. See the comments at the
top for usage.

CompareGCStats

Compares the output from two runs of PrintGCStats (presumably before
and after) and shows the percent change for the various statistics.

Basic Examples

Here's how I typically use these, given 2 log files with
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps output (say ref.log is from
the reference VM, new.log is from a modified VM that I'm evaluating):

        $ PrintGCFixup ref.log > ref.fix
        $ PrintGCFixup new.log > new.fix
        $ PrintGCStats -v cpus=4 ref.fix > ref.stats
        $ PrintGCStats -v cpus=4 new.fix > new.stats
        $ CompareGCStats ref.stats new.stats > new.comp

Below is an example of the result, new.comp.  In the pairs of lines that
have the same label, the first is from ref.stats and the second is from
new.stats; the unlabeled line that follows shows the %change.  E.g.,
this run shows that the average 'gen1t(s)' (Full GC time in seconds),
improved by 14% and the max improved by 24%.

ref.stats vs. new.stats
what           count          total        mean         max   stddev
gen0t(s)        1479        167.596     0.11332       0.452   0.0906
gen0t(s)        1487        169.604     0.11406       0.463   0.0910
               0.541%         1.198%    0.65302%      2.434%  0.4415%
gen1t(s)          80         95.982     1.19977       1.903   0.1945
gen1t(s)          90         92.594     1.02882       1.430   0.1206
              12.500%        -3.530%  -14.24856%    -24.855% -37.9949%
GC(s)           1559        263.577     0.16907       1.903   0.2592
GC(s)           1577        262.198     0.16626       1.430   0.2317
               1.155%        -0.523%   -1.66203%    -24.855% -10.6096%
alloc(MB)       1479      96679.169    65.36793      66.000   2.5605
alloc(MB)       1487      97085.999    65.28984      66.000   2.7041
               0.541%         0.421%   -0.11946%      0.000%  5.6083%
promo(MB)       1479       3235.751     2.18780      34.328   4.3802
promo(MB)       1487       3471.243     2.33439      34.305   4.4127
               0.541%         7.278%    6.70034%     -0.067%  0.7420%
used(MB)        1479     235279.202   159.07992     244.425  66.0007
used(MB)        1487     236180.818   158.83041     243.941  65.8061
               0.541%         0.383%   -0.15685%     -0.198% -0.2948%
commit0(MB)     1479     113883.000    77.00000      77.000   0.0000
commit0(MB)     1487     114499.000    77.00000      77.000   0.0000
               0.541%         0.541%    0.00000%      0.000%  0.0000%
commit1(MB)     1479     254388.000   172.00000     172.000   0.0000
commit1(MB)     1487     255764.000   172.00000     172.000   0.0000
               0.541%         0.541%    0.00000%      0.000%  0.0000%
commit(MB)      1479     368271.000   249.00000     249.000   0.0000
commit(MB)      1487     370263.000   249.00000     249.000   0.0000
               0.541%         0.541%    0.00000%      0.000%  0.0000%

alloc/elapsed_time    =  96679.169 MB /   4920.718 s  =  19.647 MB/s
alloc/elapsed_time    =  97085.999 MB /   4920.171 s  =  19.732 MB/s  
0.433%
alloc/tot_cpu_time    =  96679.169 MB /  19682.872 s  =   4.912 MB/s
alloc/tot_cpu_time    =  97085.999 MB /  19680.684 s  =   4.933 MB/s  
0.428%
alloc/mut_cpu_time    =  96679.169 MB /  18628.563 s  =   5.190 MB/s
alloc/mut_cpu_time    =  97085.999 MB /  18631.892 s  =   5.211 MB/s  
0.405%
promo/elapsed_time    =   3235.751 MB /   4920.718 s  =   0.658 MB/s
promo/elapsed_time    =   3471.243 MB /   4920.171 s  =   0.706 MB/s  
7.295%
promo/gc0_time        =   3235.751 MB /    167.596 s  =  19.307 MB/s
promo/gc0_time        =   3471.243 MB /    169.604 s  =  20.467 MB/s  
6.008%
gc_seq_load           =   1054.309 s  /  19682.872 s  =   5.356%
gc_seq_load           =   1048.792 s  /  19680.684 s  =   5.329%  -0.027%
gc_conc_load          =      0.000 s  /  19682.872 s  =   0.000%
gc_conc_load          =      0.000 s  /  19680.684 s  =   0.000%   0.000%
gc_tot_load           =   1054.309 s  /  19682.872 s  =   5.356%
gc_tot_load           =   1048.792 s  /  19680.684 s  =   5.329%  -0.027%

Note that the alloc (allocation) and promo (promotion) statistics are
not exact; they're useful only as a general indication of how much
allocation/promotion was done.

You can aggregate the statistics from multiple runs by including
additional file names on the command line.

        $ PrintGCStats -v cpus=4 ref-1.fix ref-2.fix ref-3.fix > ref.stats
        $ PrintGCStats -v cpus=4 new-1.fix new-2.fix new-3.fix > new.stats

>                                            Maybe the openJDK project
> needs this kind of script to generate some visual display, or
> something else similar to the GCSpy
> (http://www.cs.kent.ac.uk/pubs/2002/1426/)
used in JikesRVM project.

Yes, we're definitely looking for/working toward something to easily
enable visual display.  IIRC, the overhead of GCSpy was higher than many
would be willing to tolerate in production, at least for some of the
features.  Tony may be able to provide more detail.

-John
 
CD: 5ms