Monday, July 13, 2009

Extanding your troubleshooting facilities - Always on verbose GC

Getting it right the first time

What happens when customers are experiencing problems with you application in production? The customer would send you the various logs artifacts and, ideally, you should be able to diagnose the problem and provide a resolution. If you find yourself sending the customer back and forth in an effort to gather additional types of log artifacts and system information, then you are, must likely, doing something wrong.

Who should be helping you

If you deploy your application on top of a application server platform, like Websphere Application Server (WAS) in my case, the platform should be assisting with automatic logs generation and collection. Our development team has been increasingly relying on such services provided by WAS, like: FFDC, WAS Collector, hung threads detection. All of which honorably earned their production stripes and badges.

garbage2One new serviceability artifact that I have long ago really wanted to have in production was the verbose GC, this feature records the JVM garbage collection activity over time, providing insight for resolving issues such as: stop-the-world performance freezes, memory leaks, native heap corruption, etc.

Until today, I was reluctant to enable the verbose GC in production, since I believed that there's no way to direct the verbose GC output from the native stder (default) to a rotating dedicated file, not doing so might lead to files larger than 2GB (a problem on some file systems), or would cause the system to run out of disk space. I was assuming that the performance implications would be negligible, but still, you have to be extra prudent when it comes to live customers environments.

Taking out the garbageA trigger for action

Last week I had an issue with a WAS component, after opening a ticket with Websphere support, I was asked to reproduce the scenario in order to generate verbose GC output, I decided that enough is enough! I'm gonna look into the GC output file rollover issue again and see what solutions exist, what the community have to say about it, or whether there might be some other custom solution (with the Apache web server, for example, the file rolling is handled by an external process into which the log output is redirected, the process then does the rolling files management itself).

Following a quick search, I was happy to find that the IBM JVM offers a rolling over verbose GC. I quickly found additional hands on reports, Chris Bailey published verbose GC performance impact results that reassured my gut feeling about any performance impact being a non issue.

Here's the syntax: (quoting the IBM Java 6 diagnostics guide):

Causes -verbose:gc output to be written to the specified file. If the file cannot be found, -verbose:gc tries to create the file, and then continues as normal if it is successful. If it cannot create the file (for example, if an invalid filename is passed into the command), it redirects the output to stderr.
If you specify and the -verbose:gc output is redirected to X files, each containing Y GC cycles.

Final thoughts

  1. I don't like having to specify the entire path for the file files, the default path should have been the server's logs directory, or the CWD (CWD is the profile's directory I believe).

  2. Rollover threshold parameter - I would rather be specifying it in units of max MBs instead of in units of the number of GC cycles entries. I've empirically found that 1MB of verbose GC log translates to ~700 GC cycle entries (YMMV).

  3. Good enough. I'll start doing the preparations to put this into production.


  1. Nice entry on GC log rotation. Would you happen to know if there is a similar option for Sun's JVM?

  2. Didn't find anything in a 60 seconds search on Google.
    The syntax for these things is completely different from one JVM to the other.
    It could be that there's no such thing for Sun's JVM...
    No idea then. Let me know if you find anything.

  3. same results after way more than a 60 second search on google. I'm painfully aware that the jvm's have different options. I support both Sun's and IBM's jvm but was hoping to find something similar for the Sun jvm. I guess I'll have to setup a script to rotate the log, what a pain.

  4. Ted, I believe all log files, of all types should be roll able.

    You could just have it enabled on the IBM JVM and not enabled in the Sun JVM (50% benifith with 1% work).

    If on Sun the GC log is printed to the standard error, you could re-direct it (linux assumed) to Apache's rotatelogs utility.
    Just an idea.

    Good luck on that.

  5. Hotspot uses something ugly like this (since 7U02):

    java -Xloggc:log/app.vgc
    -XX:GCLogFileSize=10M -XX:NumberOfGCLogFiles=10 -XX:+UseGCLogFileRotation
    -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:-PrintGCTimeStamps