Extracting Garbage Collection messages from a WebLogic Server log file

Introduction

Here is a sample code to show how to extract JVM GC statistics from JVM log files.

Main Article

Recently, I was doing some work on tuning Garbage Collection in a HotSpot JVM (Sun JVM) underneath WebLogic Server 10.3.3.  In order to do this, I wanted to look at the Garbage Collection logs.  The JVM will produce these logs for you if you pass in the following parameters:

  • -XX:+PrintGCTimeStamps
  • -XX:+PrintGCDetails
  • -Xloggc:gc.log

In this particular case though, only the first two had been specified.  The third one produces a nice clean Garbage Collection log file that can be used with various tools to help with tuning, but unfortunately I did not get that file.  All I had was the WebLogic Server log file, with GC messages spread all through it.  This log file was several hundreds of thousands of lines in size, so manually editing it was not an option.  Re-running this application with the extra setting to capture a nice, clean log file was not a viable option either.

Solution: I wrote a small Java program to go through the WebLogic Server logs and strip out just the information I needed.  Will I ever need to use this again?  Maybe not, but I thought I would post it here for prosperity anyway.  You never know when you are going to need something like this.

Here is the Java code for my CleanGCLog class:

# Copyright 2012 Oracle Corporation. 
# All Rights Reserved. 
# 
# Provided on an 'as is' basis, without warranties or conditions of any kind, 
# either express or implied, including, without limitation, any warranties or 
# conditions of title, non-infringement, merchantability, or fitness for a 
# particular purpose. You are solely responsible for determining the 
# appropriateness of using and assume any risks. You may not redistribute.

import java.io.FileNotFoundException;
import java.io.FileReader;

public class CleanGCLog {

    public static void main(String[] args) throws Exception {
        char currentChar = 0;
        boolean print = false;
	FileReader inputStream = null;

	// Check if the right number of arguments passed in
	if (args.length != 1) {
  	    System.out.println("\nCleanGCLog\n----------\n" +
	    	"This program will  read through the input  file and print out\n" +
    		"any GC messages found to the stdout.  You need to provide the\n" +
		"filename as an argument.\n" +
  	    	"   e.g. java CleanGCLog mylogfile.log\n\n");
	    System.exit(1);
	}

        // Try to open the file
	try {
            inputStream = new FileReader(args[0]);
	} catch (Exception e) {
 	    System.out.println("Could not open the input file.");
	    e.printStackTrace();
	    System.exit(1);
	}

	// Read through the file a character at a time
        while (currentChar != (char) -1)
        {
            currentChar = (char) inputStream.read(); 

	    // Look for the start of a GC message
            if (currentChar == '{') {
                print = true;
            }
            if (print == true) {
                System.out.print(currentChar);
            }
	    // Look for the end of a GC message
            if (currentChar == '}') {
                System.out.println("}");
                print = false;
            }
        }

        inputStream.close();
    }
}

This is compiled with javac CleanGCLog.java and will produce a single class file, CleanGCLog.class which can be run as shown below.  If you run it without any arguments, it will print its usage information.

In the sample below, I have just kept the first two GC messages to show you what they look like.  This file actually had several thousand of them.  The output is just written to the stdout, so you can easily redirect it to a file or pipe it to another command if desired.

mark$ java CleanGCLog ../gc.log.112710091630.log
{Heap before GC invocations=0 (full 0):
 par new generation   total 3909824K, used 3723648K [0x00002aaaae1f0000, 0x00002aaba81f0000, 0x00002aaba81f0000)
  eden space 3723648K, 100% used [0x00002aaaae1f0000, 0x00002aab91650000, 0x00002aab91650000)
  from space 186176K,   0% used [0x00002aab91650000, 0x00002aab91650000, 0x00002aab9cc20000)
  to   space 186176K,   0% used [0x00002aab9cc20000, 0x00002aab9cc20000, 0x00002aaba81f0000)
 concurrent mark-sweep generation total 14385152K, used 0K [0x00002aaba81f0000, 0x00002aaf161f0000, 0x00002aaf161f0000)
 concurrent-mark-sweep perm gen total 524288K, used 158566K [0x00002aaf161f0000, 0x00002aaf361f0000, 0x00002aaf361f0000)
2010-11-27T09:17:17.951+1100: 47.077: [GC 47.077: [ParNew
Desired survivor size 95322112 bytes, new threshold 1 (max 15)
- age   1:  109823768 bytes,  109823768 total
: 3723648K->108098K(3909824K), 0.3358110 secs] 3723648K->108098K(18294976K), 0.3360230 secs] [Times: user=0.71 sys=0.54, real=0.33 secs] 
Heap after GC invocations=1 (full 0):
 par new generation   total 3909824K, used 108098K [0x00002aaaae1f0000, 0x00002aaba81f0000, 0x00002aaba81f0000)
  eden space 3723648K,   0% used [0x00002aaaae1f0000, 0x00002aaaae1f0000, 0x00002aab91650000)
  from space 186176K,  58% used [0x00002aab9cc20000, 0x00002aaba35b08e8, 0x00002aaba81f0000)
  to   space 186176K,   0% used [0x00002aab91650000, 0x00002aab91650000, 0x00002aab9cc20000)
 concurrent mark-sweep generation total 14385152K, used 0K [0x00002aaba81f0000, 0x00002aaf161f0000, 0x00002aaf161f0000)
 concurrent-mark-sweep perm gen total 524288K, used 158566K [0x00002aaf161f0000, 0x00002aaf361f0000, 0x00002aaf361f0000)
}
{Heap before GC invocations=1 (full 0):
 par new generation   total 3909824K, used 3831746K [0x00002aaaae1f0000, 0x00002aaba81f0000, 0x00002aaba81f0000)
  eden space 3723648K, 100% used [0x00002aaaae1f0000, 0x00002aab91650000, 0x00002aab91650000)
  from space 186176K,  58% used [0x00002aab9cc20000, 0x00002aaba35b08e8, 0x00002aaba81f0000)
  to   space 186176K,   0% used [0x00002aab91650000, 0x00002aab91650000, 0x00002aab9cc20000)
 concurrent mark-sweep generation total 14385152K, used 0K [0x00002aaba81f0000, 0x00002aaf161f0000, 0x00002aaf161f0000)
 concurrent-mark-sweep perm gen total 524288K, used 229038K [0x00002aaf161f0000, 0x00002aaf361f0000, 0x00002aaf361f0000)
2010-11-27T09:50:55.024+1100: 2064.149: [GC 2064.149: [ParNew
Desired survivor size 95322112 bytes, new threshold 1 (max 15)
- age   1:  145857248 bytes,  145857248 total
: 3831746K->186176K(3909824K), 2.3871680 secs] 3831746K->310053K(18294976K), 2.3873730 secs] [Times: user=3.95 sys=3.11, real=2.39 secs] 
Heap after GC invocations=2 (full 0):
 par new generation   total 3909824K, used 186176K [0x00002aaaae1f0000, 0x00002aaba81f0000, 0x00002aaba81f0000)
  eden space 3723648K,   0% used [0x00002aaaae1f0000, 0x00002aaaae1f0000, 0x00002aab91650000)
  from space 186176K, 100% used [0x00002aab91650000, 0x00002aab9cc20000, 0x00002aab9cc20000)
  to   space 186176K,   0% used [0x00002aab9cc20000, 0x00002aab9cc20000, 0x00002aaba81f0000)
 concurrent mark-sweep generation total 14385152K, used 123877K [0x00002aaba81f0000, 0x00002aaf161f0000, 0x00002aaf161f0000)
 concurrent-mark-sweep perm gen total 524288K, used 229038K [0x00002aaf161f0000, 0x00002aaf361f0000, 0x00002aaf361f0000)
}

Add Your Comment