Extracting Garbage Collection messages from a WebLogic Server log file

Recently, I was doing some work on tuning Garbage Collection in a HotSpot JVM (i.e. “the 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:

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)
}

About Mark Nelson

Mark Nelson is an Architect (an "IC6") in the Fusion Middleware Central Development Team at Oracle. Mark's job is to make Fusion Middleware easy to use in the cloud and at home, for developers and operations folks, with special focus on continuous delivery, configuration management and provisioning - making it simple to manage the configuration of complex environments and applications built with Oracle Database, Fusion Middleware and Fusion Applications, on-premise and in the cloud. Before joining this team, Mark was a senior member of the A-Team since 2010, and worked in Sales Consulting at Oracle since 2006 and various roles at IBM since 1994.
This entry was posted in Uncategorized and tagged , , , . Bookmark the permalink.

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s