[site-logo] LateNightHacking -> Louis -> Projects -> 2004 -> Auth
Java GC Log Viewer

2004-03-5 : I was having problems with one of my Java apps at work which I suspected was GC (garbage collection) related. Conveniently, Java has a switch you can use to turn on GC logging. The resulting log files look something like this: 

4.238: [GC 28543K->27563K(33188K), 0.0225530 secs]
4.329: [GC 29675K->28726K(33188K), 0.0204620 secs]
4.424: [GC 30838K->29889K(33188K), 0.0192290 secs]
4.521: [GC 32001K->31050K(33188K), 0.0188990 secs]
4.587: [GC 33162K->32155K(34340K), 0.0237150 secs]
4.611: [Full GC 32155K->29298K(34340K), 0.5322610 secs]
5.262: [GC 32690K->31518K(52608K), 0.0375240 secs]
5.410: [GC 34910K->33477K(52608K), 0.0406830 secs]
5.576: [GC 36869K->35343K(52608K), 0.0326430 secs]
5.737: [GC 38735K->37160K(52608K), 0.0351080 secs]
5.854: [GC 40552K->38886K(52608K), 0.0404190 secs]
While this has useful information, it's hard to visualize the performance over a long period or find the one interesting line out of thousands.

After getting a log from my problem app, the first thing I did was load it into Excel. After a couple passes of Text to columns..., I was able to "parse" out all the fields and then with some more work I was able to get a graph. It was easy to see what was happening with the graph, but it was a lot of steps to go through every time I wanted to see the GC behavior.

My first idea was to write a script to parse the log and convert it into a CSV file that Excel could read directly. This I did without too much trouble (and the final script still has this capability). However, I quickly realized that creating the graph also took a bunch of steps, and I'd rather just go straight to the graph.

I knew that MS Office has an ActiveX charting control, basically a version of Excel's charts that you can display in a web page. I decided to have the script produce an HTML file containing a graph of the log.

Here (536K) is an example web page containing a GC graph. Here (22K) is a small screenshot of the results if the web page doesn't work for you.

In the graph, the time runs along the bottom X-axis and is marked off in hours. The VM size, start size, and end size are plotted against the left Y-axis in KB. The duration of the GC event is plotted against the right Y-axis in seconds. GC events are marked with diamonds to make it easy to find the long-running full GC's. As you can see in the example, the longest full GC took over six seconds. This is a problem for my app, since incoming data can only be buffered for about four seconds.

I started out using the API to access the charting control, and managed to produce almost exactly what I wanted. However, I couldn't figure out how to get a dual Y-axis graph, even though I was able to produce one with Excel's export to web page feature. After banging my head on it for quite a while, I decided that the only way to do so was through the XML interface. I changed the script to produce an XML description of the graph and load that into the charting control, and now everything works great!

Usage: 

Usage: cscript translateGcLog.js -file {gc.log} {-csv|-html} [-startTime 0h0m0.0s] > gc.html

You can get the source via anonymous CVS at

  • cvs -d :pserver:anon@www.latenighthacking.com:/code-cvsroot co 2004/translateGcLog

    Due to popular demand, you can download the script as a zip file: translateGcLog.zip

    C o m m e n t s :     updated: 2008-11-21 (10 days ago)
    How do I run cscript with XML interface? What do I need?
    Thanks.
    -pete

    14:42 EST
    Aug. 25 2004
    2004-08-26 : I'm not quite sure what you're asking. CSript is a standard Windows component for interpreting scripts in languages such as JScript and VBScript. If you want to know how to control CScript with XML, search MSDN for documentation on Windows Scripting Host. Assuming you are talking about my script called translateGcLog.js, it does not convert a Java GC log to XML format. It does produce CSV format, and you are free to modify it to produce XML. If you do, I would appreciate it if you could send the modifications back to me. What my script does produce is a web page (HTML file) containing an MSO graph which has been serialized in XML format. The comand line to do this is described above, but to give an explicit example, you might say:
       cscript translateGcLog.js -file gc.log -html > output.html
    To do this, you need a copy of the script and a GC log file from a Java program. CScript is probably already installed, but if not you can down load it from MSDN. To view the resulting web page, you need a web browser. To view the graph on the web page, you need to have Office installed.
    -- Louis
    8th of April 2005
    Note: in order to be able to view the chart in the generated html file - gc.html -
    the chart control declaration in this file might need to differ with different Office installations.
    msdn doc:
    http://msdn.microsoft.com/library/default.asp?url=/library/en-us/modcore/html/deovrunderstandingchartcontrol.asp :
    "The CLSID for the Chart control and all the objects and related methods and properties for the control are documented in the owcvba10.chm Help file.
    Note The path to the owcvba10.chm Help file reflects the language ID folder (1033) for U.S. English language support in Office. The language ID folder c:\program files\common files\microsoft shared\web components\10\<langid>differs for each language."

    For example, in order to be able to get the chart to diplay in the (Internet Explorer) web browser,
    I needed to change the original chart control declaration:
    <object id="ChartSpace" Stye="margin:0px;" classid="CLSID:0002E500-0000-0000-C000-000000000046" style="width:100%;height:100%"></object>
    with:
    <object id=ChartSpace classid=CLSID:0002E556-0000-0000-C000-000000000046 style="width:100%;height:350"></object>
    --Ada
    (15 OCT 2008) : Hi, I tried using this script but I am getting parse exception on the first line itself of my GC log file.
    It shows following...
    \translateGcLog.js(223, 13) (null): could not parse line: 0.299: [GC 0.299: [ParNew: 3968K->0K(4032K), 0.0094598 secs] 3968K->901K(131008K), 0.0095716 secs]
    I tried with two or three different GC log files, but it shows the asme thing.
    Can someone please help.
    Thanks
    -- (Neo)



    Hi Louis,

    I too get the same parsing error at first line of the GC log file. It seems the regular expression in the script is not compatible with the GC log we've used. Can you please help on this?

    My GC log file starts like this:

    0.213: [GC 3395K(524224K), 0.0030720 secs]
    1.106: [ParNew 21120K->1735K(524224K), 0.0225190 secs]
    1.622: [GC 13147K(524224K), 0.0154590 secs]
    2.838: [ParNew 22855K->5068K(524224K), 0.0142300 secs]
    3.347: [GC 11785K(524224K), 0.0040440 secs]
    4.708: [ParNew 26188K->5616K(524224K), 0.0044100 secs]
    6.327: [GC 16532K(524224K), 0.0075370 secs]
    7.846: [ParNew 26654K->6178K(524224K), 0.0032960 secs]
    8.253: [GC 14002K(524224K), 0.0051580 secs]
    9.455: [ParNew 27298K->8701K(524224K), 0.0156190 secs]
    9.668: [GC 19829K(524224K), 0.0111840 secs]
    9.829: [ParNew 29465K->11165K(524224K), 0.0127090 secs]

    Following is the error I get when run.

    cscript translateGcLog.js -file gc.log_GENWASP_20081121.log -html > output.html
    translateGcLog.js(223, 13) (null): could not parse line:
    0.213: [GC 3395K(524224K), 0.0030720 secs]

    Will you be able to help me on this?

    Kind Regards,
    Dishan
    Edit
    Louis K. Thomas <louiNØSP@Msth@hotmÑOSP@Mail.coNÕSP@Mm> Fight Spam! Auth 2006-08-29 (825 days ago)