Dominique Gallot's weblog

__LINE__ __FILE__ macro for java. Instrumentation, Bytecode manipulation ab’USE

While driving back home, I was thinking about a use for the Instrumentation of java, and I thought of implementing the __LINE__ macro like in c.

Instrumentation what is that ? An instrumentation service is a way of modifying the loaded java bytes code on the fly, before it really exists in the jvm. The main usages of services are to implements memory profiling, code profiling and most ( all ? ) AOP frameworks.

__LINE__ __FILE__ for java

As you know, as a java developer you do not have access to a preprocessor. Most of the time, you can live with it. But when it comes to logging, it is another thing. If you are like me, most of the time you want to print with your log statement, with the classname/file name which issued the log statement and also want to see the line number.
Good logging framework provides this, but how it is fetching the information is amazingly slow.
When the logging framework needs to locate the location of the log statement, it needs to get a snapshoot of the calling stack, then needs to guess who is the caller, by carefully examining it.

Let’s examine the code which does this in the logging framework provided with the jdk ( java.util.logging.* )

// Private method to infer the caller's class and method names
private void inferCaller() {
	needToInferCaller = false;
	// Get the stack trace.
	StackTraceElement stack[] = (new Throwable()).getStackTrace();
	// First, search back to a method in the Logger class.
	int ix = 0;
	while (ix < stack.length) {
	    StackTraceElement frame = stack[ix];
	    String cname = frame.getClassName();
	    if (cname.equals("java.util.logging.Logger")) {
		break;
	    }
	    ix++;
	}
	// Now search for the first frame before the "Logger" class.
	while (ix < stack.length) {
	    StackTraceElement frame = stack[ix];
	    String cname = frame.getClassName();
	    if (!cname.equals("java.util.logging.Logger")) {			 
		// We've found the relevant frame.
	        setSourceClassName(cname);
	        setSourceMethodName(frame.getMethodName());
		  // I do not understand why they do not try to load the getLineNumber 
		return;
	    }
	    ix++;
	}
	// We haven't found a suitable frame, so just punt.  This is
        // OK as we are only committed to making a "best effort" here.
    }

A lot of code just to detect the caller, isn'it ? And even more it does not work all the time! In the following example, the line number will be improperly guessed!

public class Test {
  Logger logger = Logger.getLogger( Test.class.getName() );
  public void main() {
    error( “Error in main” );  					<-- I want this line
  }

  private void error( String message ) {
    logger.sever( message ) 						<-- I wll be getting this one
  }
}

You are basically not allowed to pass by any other method before logging!

My solution

Is to define some static fields which will be returning the __FILE__ ...
And behind the scene I use the instrumentation, byte code manipulation, and the available debug information to dynamically add the correct file/line number.

Here is how to use it

package com.dg.test;

import static com.dg.ab.use.instument.CodeLocation.__FILE__;
import static com.dg.ab.use.instument.CodeLocation.__LINE__;
import static com.dg.ab.use.instument.CodeLocation.__FILE_LINE__;

public class CodeLocationTest {
	public void run() {
		System.err.println( __FILE_LINE__ );
		System.err.println( __FILE_LINE__ + ": Entering in run method" );
		System.err.println( __FILE_LINE__ + ": Entering in run method" );
		for ( int i = 0; i < 10; i++ ) {
			System.err.println( __FILE__ + ":" + __LINE__ + " value of i is '"+i+"'");
		}
	}
	public static void main( String args[] ) {
		new Test().run();
	}
}

Thanks to the static import, it really looks like c code isn’t it ? And when running it with the appropriate agent ( adding -javaagent:CodeLocationAgent.jar to you java parameter), the __LINE__, __FILE__, __FILE_LINE__ will be properly replaced, and give this result !

CodeLocationTest.java:9
CodeLocationTest.java:10: Entering in run method
CodeLocationTest.java:11: Entering in run method
CodeLocationTest.java:13 value of i is '0'
CodeLocationTest.java:13 value of i is '1'
CodeLocationTest.java:13 value of i is '2'
CodeLocationTest.java:13 value of i is '3'
CodeLocationTest.java:13 value of i is '4'
CodeLocationTest.java:13 value of i is '5'
CodeLocationTest.java:13 value of i is '6'
CodeLocationTest.java:13 value of i is '7'
CodeLocationTest.java:13 value of i is '8'
CodeLocationTest.java:13 value of i is '9'

Want to try ? Download the code from my svn repository, and run the Test.launch run configuration.

If you are sceptic about the performance boost, I even made a comparison of both systems.
Just run the testcase Speedtest, which is running about 1OOO times the same test, but disable the output stream to remove the lag of logging to the console.
The result ?

By inferring the location : 400 ms
Using the CodeLocationAgent : 50 ms

But of course without counting time took to process the class bytecode.

Next week I will explain you how I did it easily, with the help of the ASM library!
But in the meantime, you can check the source code on the svn.

Sources :

The agent code svn repository is http://svn.gallot.be/blog/Instument-abUse/Instrument-abUse/
The test code svn repository is http://svn.gallot.be/blog/Instument-abUse/Instrument-abUse-tets/