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.

One 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.

A 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):

-Xverbosegclog[:<file>[,<X>,<Y>]]
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.