The Server Labs Blog Rotating Header Image

log

Human readable JVM GC timestamps

When we are diagnosing problems in a Java (EE or otherwise) application, is often a good idea to check how garbage collection is performing. One of the basic and most unobtrusive actions is to enable garbage collection logging.

As you may know, if we add the following arguments to the java start command…

-Xloggc:<file_name> –XX:+PrintGCDetails -XX:+PrintGCDateStamps

… the JVM will start writing garbage collection messages to the file we set with the parameter -Xlogcc. The messages should be something like:


2010-04-22T18:12:27.796+0200: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828+0200: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859+0200: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890+0200: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

The bold part is simply the date and time when reported garbage collection event starts.

Unfortunately -XX:+PrintGCDateStamps is available only for Java 6 Update 4 and later JVMs. So, if we are unlucky and our application is running on older JVMs we are forced to use…

-Xloggc:<file> –XX:+PrintGCDetails

… and the messages will be like:


22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

Now, the bold numbers (also present in previous format) are the seconds elapsed from JVM start time.

Mmm… way harder to correlate GC events with information from other log files in this case :/

Wouldn’t it be easier to process the gc log file and calculate date and time from seconds elapsed? It seems so, but seconds elapsed from… when? Or, putting it in other words, where do we extract the JVM startup date and time from?

In order to be as unobtrusive as possible, we should try to calculate the start date and time from the same GC log file. That brings us to the file attributes. We have different options:

Unix Windows
Access time Access time
Change time Creation time
Modify time Modify time

We discard access time (for obvious reasons) and change time and creation time as they are not available in both platforms, so we are left with modification time, which represents the time when the file was last modified.

In Windows, modification time is maintained when the file is copied elsewhere, but in Unix we should use the -p flag to preserve timestamp attributes if we want to copy the GC log file prior to our processing.

The last modification time of the GC log file should match the last timestamp recorded for a GC event in the log file. Well… for the purists, it should match exactly the last elapsed time plus the execution time (both in bold) as each log line is written piece by piece as it executes.


22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

In our approach, we discard the execution time as we don’t need accurate precision to have a rough idea of what time each garbage collection event occurred. Nevertheless, keep in mind that GC execution time could sometimes be as long as several seconds in large heaps.

When we experienced this situation in a client recently, we needed to quickly develop a simple and portable script, so we used Python for the task. You already knew we don’t do just Java, didn’t you? 😛

#!/usr/bin/env python

import sys, os, datetime

# true if string is a positive float
def validSeconds(str_sec):
    try:
        return 0 < float(str_sec)
    except ValueError:
        return False
                
# show usage                
if len(sys.argv) < 2:
    print "Usage: %s " % (sys.argv[0])
    sys.exit(1)
    
file_str = sys.argv[1]
lastmod_date = datetime.datetime.fromtimestamp(os.path.getmtime(file_str))

file = open(file_str, 'r')
lines = file.readlines()
file.close()

# get last elapsed time
for line in reversed(lines):
    parts = line.split(':')
    if validSeconds(parts[0]):
        break

# calculate start time
start_date = lastmod_date - datetime.timedelta(seconds=float(parts[0]))
  
# print file prepending human readable time where appropiate  
for line in lines:
    parts = line.split(':')
    if not validSeconds(parts[0]):
        print line.rstrip()
        continue
    line_date = start_date + datetime.timedelta(seconds=float(parts[0]))
    print "%s: %s" % (line_date.isoformat(), line.rstrip())

The script output can be redirected to another file, where we’ll have

2010-04-22T18:12:27.796375: 22.317: [GC 59030K->52906K(97244K), 0.0019061 secs]
2010-04-22T18:12:27.828375: 22.348: [GC 59114K->52749K(97244K), 0.0021595 secs]
2010-04-22T18:12:27.859375: 22.380: [GC 58957K->53335K(97244K), 0.0022615 secs]
2010-04-22T18:12:27.890375: 22.409: [GC 59543K->53385K(97244K), 0.0024157 secs]

You may note the date format is not 100% the same as the one with -XX:+PrintGCDateStamps argument, but it should be enough to get an idea of when each GC event happened (Timezone management in Python is way out of the scope of this blog entry).

This has been my first blog entry for The Server Labs and I hope some of you find it useful. Of course, all comments, suggestions and feedback are very welcome.