Home > Articles > Programming > Java

Java Reference Guide

Hosted by

Toggle Open Guide Table of ContentsGuide Contents

Close Table of ContentsGuide Contents

Close Table of Contents

Code Tracing

Last updated Mar 14, 2003.

Before we dive into instrumenting the bytecode of classes we load into the JVM to perform code tracing, we need to review how we're going to perform the tracing in the first place. It may seem easy on the surface: set some kind of timer when a method starts, add another when the next method starts, etc. But that gets complicated because not only do we want to record the response time of individual methods but we also want to record the method traces, or the order in which methods call each other. We can solve this by maintaining some sort of “trace manager” that keeps track of all of this information for us, for example, we tell the trace manager when a method starts and ends, but chances are that we are eventually going to want to run this in some sort of complicated multi-threaded environment such as a servlet container.

What we would like to do is find some area of memory that we could use on a per-thread basis where we could store the start times and end times of methods. The solution to this problem is the ThreadLocal class. The Javadoc describes it as follows:

    “This class provides thread-local variables. These variables differ from their normal counterparts in that each thread that accesses one (via its get or set method) has its own, independently initialized copy of the variable. ThreadLocal instances are typically private static fields in classes that wish to associate state with a thread (e.g., a user ID or Transaction ID) ... Each thread holds an implicit reference to its copy of a thread-local variable as long as the thread is alive and the ThreadLocal instance is accessible; after a thread goes away, all of its copies of thread-local instances are subject to garbage collection (unless other references to these copies exist).”

To easily implement a tracing solution we're going to employ two core classes:

  • Trace: maintains a list of “actions”, such as the start of a method, the end of a method, or the exceptional exit of a method, as well as the timestamp when the action occurred.
  • Tracer: a class that extends ThreadLocal and exposes the Trace element for the current thread.

And we're going to need two helper classes:

  • MethodAction: as described above, a method action denotes the start, end, or exceptional exit of a method and maintains the timestamp in which the action occurred
  • TraceManager: when a trace ends, the trace is sent to the TraceManager, which maintains all traces for the threads running in the JVM.

Listing 1 starts with the simplest of these classes, the MethodAction class.

Listing 1. MethodAction.java

package com.geekcap.openapm.trace;

import java.io.Serializable;

/**
 * Defines a method action, which is either the start or end of a method. It records
 * the timestamp of the action as well as the id, which is the fully qualified method name.
 *
 * @author shaines
 */
public class MethodAction implements Serializable
{
    private static final long serialVersionUID = 1L;
    
    /**
     * Is the method starting, ending, or did it throw an exception?
     */
    public enum Action
    {
        START, END, EXCEPTION
    };

    /**
     * The action for this event: START, END, or EXCEPTION
     */
    private Action action;

    /**
     * The id for this event, which should be the fully qualified method name
     */
    private String id;

    /**
     * The timestamp when this event occurred
     */
    private long timestamp;

    /**
     * Creates a new MethodAction
     *
     * @param action        The method action: START, END, or EXCEPTION
     * @param id            The id/fully qualified name of the method
     */
    public MethodAction( Action action, String id )
    {
        timestamp = System.currentTimeMillis();
        this.action = action;
        this.id = id;
    }

    public MethodAction( long timestamp, Action action, String id )
    {
        this.timestamp = timestamp;
        this.action = action;
        this.id = id;
    }

    public Action getAction()
    {
        return action;
    }

    public void setAction( Action action )
    {
        this.action = action;
    }

    public String getId()
    {
        return id;
    }

    public void setId( String id )
    {
        this.id = id;
    }

    public long getTimestamp()
    {
        return timestamp;
    }

    public void setTimestamp( long timestamp )
    {
        this.timestamp = timestamp;
    }

    @Override
    public String toString()
    {
        return timestamp + ": [" + action + "]\t" + id;
    }
}

As you can see, the MethodAction class maintains an action (the Action enumeration is defined as a public enumeration inside the MethodAction class and defines the actions START, END, and EXCEPTION), an identifier, which will typically be the name of the method, and a timestamp. The idea is that you can create a new MethodAction of the form:

new MethodAction( MethodAction.Action.START, “MyMethod” );

MethodActions are maintained inside a Trace, shown in listing 2.

Listing 2. Trace.java

package com.geekcap.openapm.trace;

import java.io.Serializable;
import java.util.LinkedList;
import java.util.List;
import org.apache.log4j.Logger;

/**
 * A Trace is a collection of method actions
 * 
 * @author shaines
 */
public class Trace implements Serializable
{
    private static final long serialVersionUID = 1L;
    private static final Logger logger = Logger.getLogger( Trace.class );

    /**
     * The trace key, which will be assigned by the TraceManager
     */
    private String traceKey;

    /**
     * The ID of the head of the trace, which is used to identify the end of the trace
     */
    private String headId;


    /**
     * The list of MethodActions (START, END, or EXCEPTION) that participated in this trace
     */
    private List<MethodAction> actions = new LinkedList<MethodAction>();

    /**
     * Creates a new Trace
     */
    public Trace()
    {
    }

    /**
     * Adds a MethodAction to this trace, where a MethodAction may identify the
     * start of a method call, the end of a method call, or an exceptional exit of
     * a method call
     *
     * @param action            The type of action: START, END, or EXCEPTION
     * @param id                The method id, which is the fully-qualified method name
     */
    public void addAction( MethodAction.Action action, String id )
    {
        if( logger.isTraceEnabled() )
        {
            logger.trace( "Add action: [" + action + "] " + id );
        }

        if( actions.size() == 0 )
        {
            // Save the head id of this trace
            headId = id;

            // Start the trace in the TraceManager and save the key
            traceKey = TraceManager.getInstance().startTrace( this );
        }

        // Add the trace to the
        actions.add( new MethodAction( action, id ) );

        if( action == MethodAction.Action.END && id.equals( headId ) )
        {
            // Mark this trace as complete
            TraceManager.getInstance().endTrace( traceKey );
        }
    }

    /**
     * Returns the list of method actions for this trace
     *
     * @return          The list of method starts, ends, and exceptions
     */
    public List<MethodAction> getActions()
    {
        return actions;
    }

    /**
     * Setter method, used for trace file reading
     *
     * @param actions   The actions to set in this Trace
     */
    public void setActions( List<MethodAction> actions )
    {
        this.actions = actions;
    }

    public String getTraceKey()
    {
        return traceKey;
    }

    public void setTraceKey( String traceKey )
    {
        this.traceKey = traceKey;
    }
}

At its core, the Trace class only really maintains a list of MethodAction instances. It has some code logic to determine when a new trace is starting (the MethodAction list is empty) and when the trace is ending (the END action has been received for the method that started the Trace.) When a new Trace is started, the Trace obtains a trace key, or a unique identifier for the Trace, from the TraceManager so that traces can stay unique. When a Trace ends, it notifies the TraceManager that the Trace is complete and passes it that unique key. Because the Trace maintains a linked list of method actions, you could expect a trace internally to look like the following:

ParentMethod is starting (timestamp=...)
ChildMethod1 is starting (timestamp=...)
GrandChildMethod1 is starting (timestamp=...)
GrandChildMethod1 is ending (timestamp=...)
ChildMethod1 is ending (timestamp=...)
ChildMethod2 is starting (timestamp=...)
ChildMethod2 is ending (timestamp=...)
ParentMethod is ending (timestamp=...)

And this would translate to a trace tree like the following:

ParentMethod
	ChildMethod1
		GrandChildMethod1
	ChildMethod2

And for each node we could compute the cumulative response time for each method (end time – start time) as well as the time spent exclusively in each method (end time – start time – (the sum of cumulative times for each child method)).

Next, listing 3 shows the source code for the Tracer, which is the class that extends ThreadLocal.

Listing 3. Tracer.java

package com.geekcap.openapm.trace;

public class Tracer extends ThreadLocal<Trace>
{
    private static final long serialVersionUID = 1L;

    private static Tracer instance = new Tracer();

    public static Tracer getInstance()
    {
        return instance;
    }

    private Tracer()
    {
    }

    @Override
    public Trace initialValue()
    {
        return new Trace();
    }
}

The Tracer class is probably the simplest looking, in terms of code, but let's take it apart to see how it works. First, it extends ThreadLocal, which uses Java generics to define the specific type of variable that it is maintaining, and in this case the variable that the Tracer is maintaining is of type Trace. The Tracer class is a singleton, meaning that there is only one instance of the class for the thread (typically singletons mean that there is one instance for the JVM, but the fact that we extend ThreadLocal means that there is one instance for each thread.) To make a variable a singleton, you typically define an instance of it as a static member variable, define a private constructor so that no one can create an instance, and then define an accessor method such as getInstance() to control access to that single instance. In this case I opted to define the instance in the static initializer so that it is created as soon as the Tracer is created for the current thread; the alternative is to create the instance in the getInstance() method to “lazily” create the instance and then synchronize the getInstance() method to prevent multiple threads inadvertently creating multiple instances. Because this is ThreadLocal, the multithreaded concerns are gone so if you want to lazily create your Tracer, go for it.

ThreadLocal variables are accessed externally by the get() and set() methods, but internally ThreadLocal calls your class's initialValue() method to cause you to create an instance of the variable that should be “thread local” (a static instance for the current thread) and then it manages the get() and set() methods. Thus we extend initialValue() and return a new Trace instance, but when we use the Tracer we will use it through its get() method. This is how we'll add a new method action to the trace:

Tracer.getInstance().get().addAction( Action.START, "TestApp.method1" );
Tracer.getInstance().get().addAction( Action.END, "TestApp.method1" );

The getInstance() method returns the thread-scoped singleton instance of the Tracer method and then the get() method returns the Trace instance.

Finally listing 4 shows the source code for the TraceManager.

Listing 4. TraceManager.java

package com.geekcap.openapm.trace;

import com.geekcap.openapm.trace.io.TraceWriter;
import java.io.FileOutputStream;
import java.io.Serializable;
import java.util.HashMap;
import java.util.Map;
import org.apache.log4j.Logger;

/**
 * Manages all traces
 *
 * @author shaines
 */
public class TraceManager implements Serializable, Runnable
{
    private static final Logger logger = Logger.getLogger( TraceManager.class );

    private static final long serialVersionUID = 1L;

    /**
     * The instance of the TraceManager
     */
    private static TraceManager instance = new TraceManager();

    /**
     * Maintains all active traces
     */
    private Map<String, Trace> activeTraces = new HashMap<String, Trace>();

    /**
     * Maintains all traces that have been completed
     */
    private Map<String, Trace> completedTraces = new HashMap<String, Trace>();

    /**
     * True if the TraceManager thread is running false otherwise
     */
    private boolean running = false;

    private boolean started = false;

    /**
     * Counter used for ensuring that trace ids are unique
     */
    private long counter = 0;

    /**
     * Singleton accessor method
     *
     * @return          Returns the instance of the TraceManager
     */
    public static TraceManager getInstance()
    {
        return instance;
    }

    /**
     * Called by the Trace class when a trace is started
     *
     * @param trace     A reference to the Trace that is starting
     *
     * @return          A unique identifier for this trace
     */
    public synchronized String startTrace( Trace trace )
    {
        // Generate a key
        String key = Long.toString( System.currentTimeMillis() ) + "-" + counter++;

        // Put the trace in the active traces map
        activeTraces.put( key, trace );

        // We've received a trace so put the TraceManager into a started state
        if( !started )
        {
            started = true;
        }

        // Return the key to the caller
        return key;
    }

    /**
     * Signals the end of this trace
     *
     * @param key       The key identifying the trace that is ending
     */
    public void endTrace( String key )
    {
        if( activeTraces.containsKey( key ) )
        {
            // Move the trace to the completed trace map
            completedTraces.put( key, activeTraces.remove( key ) );
        }
    }

    /**
     * Persists all traces gathered by the TraceManager
     */
    private void saveTraces()
    {
        if( logger.isInfoEnabled() )
        {
            logger.info( "Saving traces" );
        }

        try
        {
            TraceWriter.write( completedTraces, new FileOutputStream( "trace-file.xml" ) );
        }
        catch( Exception e )
        {
            logger.error( "An error occurred while saving trace file: " + e.getMessage(), e );
        }

        for( String key : completedTraces.keySet() )
        {
            Trace trace = completedTraces.get( key );

            StringBuilder sb = new StringBuilder( "Trace[" ).append( key ).append( "]:\n" );
            for( MethodAction ma : trace.getActions() )
            {
                sb.append( "\t" + ma + "\n" );
            }
            System.out.println( sb.toString() );
        }
    }

    /**
     * Starts the trace manager
     */
    public void startTraceManager()
    {
        if( logger.isInfoEnabled() )
        {
            logger.info( "Starting TraceManager" );
        }

        // Set out state variables
        running = true;
        started = false;

        // Start the TraceManager in its own thread
        Thread thread = new Thread( this );
        thread.start();
    }

    /**
     * The TraceManager is configured to run in its own thread
     */
    @Override
    public void run()
    {
        if( logger.isInfoEnabled() )
        {
            logger.info( "TraceManager started" );
        }

        // Run while running is true (control to be able to manually stop the TraceManager)
        // and while he have active traces (and we have received at least one so far)
        while( ( !started || activeTraces.size() > 0 ) && running )
        {
            try
            {
                // 100ms sleep
                Thread.sleep( 100 );
            }
            catch( Exception e )
            {

            }
        }

        // Save our traces
        saveTraces();

        if( logger.isInfoEnabled() )
        {
            logger.info( "TraceManager shutting down" );
        }
    }

    /**
     * Private constructor to ensure singleton pattern
     */
    private TraceManager()
    {
    }
}

We will probably modify the TraceManager as it is adapted to work in an integration environment, but for now it maintains all active traces and once the active trace list is depleted it saves the traces to a file using a helper class called TraceWriter. Listing 5 shows the source code for the TraceWriter, but note that it is sure to change before this article series is complete.

Listing 5. TraceWriter.java

package com.geekcap.openapm.trace.io;

import com.geekcap.openapm.trace.MethodAction;
import com.geekcap.openapm.trace.Trace;
import java.io.OutputStream;
import java.util.Map;
import org.apache.log4j.Logger;
import org.jdom.Element;
import org.jdom.output.Format;
import org.jdom.output.XMLOutputter;

/**
 * Utility class that writes trace files
 *
 * @author shaines
 */
public class TraceWriter
{
    private static final Logger logger = Logger.getLogger( TraceWriter.class );

    /**
     * Writes the specified trace map to the specified output stream
     *
     * @param traces            The trace map to write
     * @param os                The output stream to which to write the trace map
     */
    public static void write( Map<String,Trace> traces, OutputStream os )
    {
        Element root = new Element( "trace-file" );
        for( String key : traces.keySet() )
        {
            // Load the trace
            Trace trace = traces.get( key );

            // Build the trace element
            Element traceElement = new Element( "trace" );
            traceElement.setAttribute( "key", key );

            // Build the content of the node
            StringBuilder sb = new StringBuilder();
            for( MethodAction ma : trace.getActions() )
            {
                sb.append( ma.getTimestamp() + "," + ma.getAction() + "," + ma.getId() + "|" );
            }
            sb.deleteCharAt( sb.length() - 1 );
            traceElement.addContent( sb.toString() );

            // Add the trace element to the document
            root.addContent( traceElement );
        }

        try
        {
            // Write the trace file to the output stream using JDOM
            XMLOutputter out = new XMLOutputter( Format.getPrettyFormat() );
            out.output( root, os );
        }
        catch( Exception e )
        {
            logger.error( "An error occurred while saving trace file: " + e.getMessage(), e );
        }
    }
}

The TraceManager class maintains its own thread so that it is assured to complete its task even after the main execution thread for your traced application completes. You can review the resultant XML file to see the details of each trace.