Modern Java™ applications are typically complex, multithreaded, distributed systems that use many third-party components. On such systems, it is hard to detect (let alone isolate) the root causes of performance or reliability problems, especially in production. Traditional tools such as profilers can be useful for cases where a problem is easy to reproduce, but the overhead imposed by such tools makes them unrealistic to use in production or even load-test environments.

A common alternative strategy for monitoring and troubleshooting application performance and failures is to instrument performance-critical code with calls to record usage, timing, and errors. However, this approach requires scattering duplicate code in many places with much trial and error to determine what code needs to be measured. This approach is also difficult to maintain as the system changes and is hard to drill into. This makes application code challenging to add or modify later, precisely when performance requirements are better known. In short, system monitoring is a classic crosscutting concern and therefore suffers from any implementation that is not modular.

As you will learn in this two-part article, aspect-oriented programming (AOP) is a natural fit for solving the problems of system monitoring. AOP lets you define pointcuts that match the many join points where you want to monitor performance. You can then write advice that updates performance statistics, which can be invoked automatically whenever you enter or exit one of the join points.

In this half of the article, I'll show you how to use AspectJ and JMX to create a flexible, aspect-oriented monitoring infrastructure. The monitoring infrastructure I'll use is the core of the open source Glassbox Inspector monitoring framework (see Resources). It provides correlated information that helps you identify specific problems but with low enough overhead to be used in production environments. It lets you capture statistics such as total counts, total time, and worst-case performance for requests, and it will also let you drill down into that information for database calls within a request. And it does all of this within a modest-sized code base!

In this article and the next one, I'll build up from a simple Glassbox Inspector implementation and add functionality as I go along. Figure 1 should give you an idea of the system that will be the end result of this incremental development process. Note that the system is designed to monitor multiple Web applications simultaneously and provide correlated statistical results.

Figure 2 is an overview of the architecture of the monitoring system. The aspects interact with one or more applications inside a container to capture performance data, which they surface using the JMX Remote standard. From an architectural standpoint, Glassbox Inspector is similar to many performance monitoring systems, although it is distinguished by having well-defined modules that implement the key monitoring functions.

Java Management Extensions (JMX) is a standard API for managing Java applications by viewing attributes of managed objects. The JMX Remote standard extends JMX to allow external client processes to manage an application. JMX management is a standard feature in Java Enterprise containers. Several mature third-party JMX libraries and tools exist, and JMX support has been integrated into the core Java runtime with Java 5. Sun Microsystems's Java 5 VM includes the JConsole JMX client.

You should download the current versions of AspectJ, JMX, and JMX Remote, as well as the source packet for this article (see Resources for the technologies and Download for the code) before continuing. If you are using a Java 5 VM, then it has JMX integrated into it. Note that the source packet includes the complete, final code for the 1.0 alpha release of the open source Glassbox Inspector performance monitoring infrastructure.

The basic system

I'll start with a basic aspect-oriented performance monitoring system. This system captures the time and counts for different servlets processing incoming Web requests. Listing 1 shows a simple aspect that would capture this performance information:

/**
 * Monitors performance timing and execution counts for 
 * <code>HttpServlet</code> operations
 */
public aspect HttpServletMonitor {
 
  /** Execution of any Servlet request methods. */
  public pointcut monitoredOperation(Object operation) : 
    execution(void HttpServlet.do*(..)) && this(operation);
 
  /** Advice that records statistics for each monitored operation. */
  void around(Object operation) : monitoredOperation(operation) {
      long start = getTime();
 
      proceed(operation);
 
      PerfStats stats = lookupStats(operation);
      stats.recordExecution(getTime(), start);
  }
 
  /**
   * Find the appropriate statistics collector object for this
   * operation.
   * 
   * @param operation
   *            the instance of the operation being monitored
   */
  protected PerfStats lookupStats(Object operation) {
      Class keyClass = operation.getClass();
      synchronized(operations) {
          stats = (PerfStats)operations.get(keyClass);
          if (stats == null) {                
              stats = perfStatsFactory.
                createTopLevelOperationStats(HttpServlet.class, 
                       keyClass);
              operations.put(keyClass, stats);
          }
      }
      return stats;        
  }
 
  /**
   * Helper method to collect time in milliseconds. Could plug in
   * nanotimer.
   */
  public long getTime() {
      return System.currentTimeMillis();
  }
 
  public void setPerfStatsFactory(PerfStatsFactory 
    perfStatsFactory) {
      this.perfStatsFactory = perfStatsFactory;
  }
 
  public PerfStatsFactory getPerfStatsFactory() {
      return perfStatsFactory;
  }
 
  /** Track top-level operations. */ 
  private Map/*<Class,PerfStats>*/ operations  = 
    new WeakIdentityHashMap();
  private PerfStatsFactory perfStatsFactory;
}
 
/**
 * Holds summary performance statistics for a 
 * given topic of interest
 * (e.g., a subclass of Servlet).
 */ 
public interface PerfStats {
  /**
   * Record that a single execution occurred.
   * 
   * @param start time in milliseconds
   * @param end time in milliseconds
   */
  void recordExecution(long start, long end);
 
  /**
   * Reset these statistics back to zero. Useful to track statistics
   * during an interval.
   */
  void reset();
 
  /**
   * @return total accumulated time in milliseconds from all
   *         executions (since last reset).
   */
  int getAccumulatedTime();
 
  /**
   * @return the largest time for any single execution, in
   *         milliseconds (since last reset).
   */
  int getMaxTime();
 
  /** 
   * @return the number of executions recorded (since last reset). 
   */
  int getCount();
}
 
/**
 * Implementation of the
 * 
 * @link PerfStats interface.
 */
public class PerfStatsImpl implements PerfStats {
  private int accumulatedTime=0L;
  private int maxTime=0L;
  private int count=0;
 
  public void recordExecution(long start, long end) {
      int time = (int)(getTime()-start);
      accumulatedTime += time;
      maxTime = Math.max(time, maxTime);
      count++;
  }
 
  public void reset() {
      accumulatedTime=0L;
      maxTime=0L;
      count=0;
  }
 
  int getAccumulatedTime() { return accumulatedTime; }
  int getMaxTime() { return maxTime; }
  int getCount() { return count; }
}
 
public interface PerfStatsFactory {
    PerfStats 
      createTopLevelOperationStats(Object type, Object key);
}
 

As you can see, this first version is fairly basic. HttpServletMonitor defines a pointcut called monitoredOperation that matches the execution of any method on the HttpServlet interface whose name starts with do. These are typically doGet() and doPost(), but it also captures the less-often-used HTTP request options by matching doHead(), doDelete(), doOptions(), doPut(), and doTrace().

Whenever one of these operations executes, the system executes an around advice to monitor performance. The advice starts a stop watch, and then it lets the original request proceed. After this, it stops the stop watch and looks up a performance-statistics object that corresponds to the given operation. It then records that the operation was serviced in the elapsed time by invoking recordExecution() from the interface PerfStats. This simply updates the total time, the maximum time (if appropriate), and a count of executions of the given operation. Naturally, you could extend this approach to calculate additional statistics and to store individual data points where issues might arise.

I've used a hash map in the aspect to store the accumulated statistics for each type of operation handler, which is used during lookup. In this version, the operation handlers are all subclasses of HttpServlet, so the class of the servlet is used as the key. I've also used the term operation for Web requests, thus distinguishing them from the many other kinds of requests an application might make (e.g., database requests). In the second part of this article, I'll extend this approach to address the more common case of tracking operations based on the class or method used in a controller, such as an Apache Struts action class or a Spring multiaction controller method.

Back to top

Exposing performance data

Once you've captured performance data, you have a wide variety of options for how to make it available. The easiest way is to write the information to a log file periodically. You could also load the information into a database for analysis. Rather than add the latency, complexity, and overhead of summarizing, logging, and processing information, it is often better to provide direct access to live system performance data. I'll show you how to do this in this next section.

I want a standard protocol that existing management tools can display and track, so I'll use the JMX API to share performance statistics. Using JMX means that each of the performance-statistics instances will be exposed as a management bean, thus yielding detailed performance data. Standard JMX clients like Sun Microsystems's JConsole will also be able to show the information. See Resources to learn more about JMX.

Figure 3 is a screenshot of the JConsole showing data from the Glassbox Inspector monitoring the performance of the Duke's Bookstore sample application (see Resources). Listing 2 shows the code that implements this feature.

Traditionally, supporting JMX involves implementing patterns with boilerplate code. In this case, I'll combine JMX with AspectJ, which enables me to write the management logic separately.

/** Reusable aspect that automatically registers
 *  beans for management
 */
public aspect JmxManagement {

    /** Defines classes to be managed and 
     *  defines basic management operation
     */
    public interface ManagedBean {
        /** Define a JMX operation name for this bean. 
         *  Not to be confused with a Web request operation.
         */
        String getOperationName();
        /** Returns the underlying JMX MBean that 
         *  provides management
         *  information for this bean (POJO).
         */
        Object getMBean();
    } 

    /** After constructing an instance of 
     *  <code>ManagedBean</code>, register it
     */
    after() returning (ManagedBean bean): 
      call(ManagedBean+.new(..)) {
        String keyName = bean.getOperationName();
        ObjectName objectName = 
          new 
            ObjectName("glassbox.inspector:" + keyName);

        Object mBean = bean.getMBean();
        if (mBean != null) {
            server.registerMBean(mBean, objectName);
        }
    }

    /** 
     * Utility method to encode a JMX key name, 
     *  escaping illegal characters.
     * @param jmxName unescaped string buffer of form 
     * JMX keyname=key 
     * @param attrPos position of key in String
     */ 
    public static StringBuffer 
      jmxEncode(StringBuffer jmxName, int attrPos) {
        for (int i=attrPos; i<jmxName.length(); i++) {
            if (jmxName.charAt(i)==',' ) {
                jmxName.setCharAt(i, ';');
            } else if (jmxName.charAt(i)=='?' 
                || jmxName.charAt(i)=='*' || 
                jmxName.charAt(i)=='\\' ) {
                jmxName.insert(i, '\\');
                i++;
            } else if (jmxName.charAt(i)=='\n') {
                jmxName.insert(i, '\\');
                i++;
                jmxName.setCharAt(i, 'n');
            }
        }
        return jmxName;
    }

    /** Defines the MBeanServer with which beans
     *   are auto-registered.
     */
    private MBeanServer server;

    public void setMBeanServer(MBeanServer server) {
        this.server = server;
    }

    public MBeanServer getMBeanServer() {
        return server;
    }
}

You can see that this first aspect is reusable. With it, I can automatically register an object instance for any class that implements an interface, ManagedBean, using an after advice. This is similar to the AspectJ Marker Interface idiom (see Resources) in that it defines the classes whose instances should be exposed through JMX. However, unlike a true marker interface, this one also defines two methods.

The aspect provides a setter to define which MBean server should be used for managing objects. This is an example of using the Inversion of Control (IOC) pattern for configuration and is a natural fit with aspects. In the full listing of the final code, you'll see I've used a simple helper aspect to configure the system. In a larger system, I would use an IOC container like the Spring framework to configure classes and aspects. See Resources for more about IOC and the Spring framework and for a good introduction to using Spring to configure aspects.

/** Applies JMX management to performance statistics beans. */
public aspect StatsJmxManagement {
    /** Management interface for performance statistics. 
     *  A subset of @link PerfStats
     */
    public interface PerfStatsMBean extends ManagedBean {
        int getAccumulatedTime();
        int getMaxTime();
        int getCount();
        void reset();
    }
    
    /** 
     * Make the @link PerfStats interface 
     * implement @link PerfStatsMBean, 
     * so all instances can be managed 
     */
    declare parents: PerfStats implements PerfStatsMBean;

    /** Creates a JMX MBean to represent this PerfStats instance. */ 
    public DynamicMBean PerfStats.getMBean() {
        try {
            RequiredModelMBean mBean = new RequiredModelMBean();
            mBean.setModelMBeanInfo
              (assembler.getMBeanInfo(this, getOperationName()));
            mBean.setManagedResource(this, 
              "ObjectReference");
            return mBean;
        } catch (Exception e) {
            /* This is safe because @link ErrorHandling
            *  will resolve it. This is described later!
            */
            throw new 
              AspectConfigurationException("can't 
                register bean ", e);
        }
    }

    /** Determine JMX operation name for this
     *  performance statistics bean. 
     */    
    public String PerfStats.getOperationName() {        
        StringBuffer keyStr = 
          new StringBuffer("operation=\"");
        int pos = keyStr.length();

        if (key instanceof Class) {
            keyStr.append(((Class)key).getName());
        } else {
            keyStr.append(key.toString());
        }
        
        JmxManagement.jmxEncode(keyStr, pos);
        
        keyStr.append("\"");
        return keyStr.toString();
    }

    private static Class[] managedInterfaces = 
      { PerfStatsMBean.class };
    /** 
     * Spring JMX utility MBean Info Assembler. 
     * Allows @link PerfStatsMBean to serve 
     * as the management interface of all performance 
     * statistics implementors. 
     */
    static InterfaceBasedMBeanInfoAssembler assembler;
    static {
        assembler = new InterfaceBasedMBeanInfoAssembler();
        assembler.setManagedInterfaces(managedInterfaces);
    }
}

Listing 3 contains the StatsJmxManagement aspect, which defines concretely which objects should expose management beans. It outlines an interface, PerfStatsMBean, that defines the management interface for any performance-statistics implementation. This consists of the statistics values for counts, total time, maximum time, and the reset operation, which is a subset of the PerfStats interface.

PerfStatsMBean itself extends ManagedBean, so that anything that implements it will automatically be registered for management by the JmxManagement aspect. I've used the AspectJ declare parents form to make the PerfStats interface extend a special management interface, PerfStatsMBean. As a result, the JMX Dynamic MBean approach manages these objects, which I prefer to using JMX Standard MBeans.

Using Standard MBeans would require me to define a management interface with a name based on each implementation class of performance statistics, such as PerfStatsImplMBean. Later, when I add subclasses of PerfStats to the Glassbox Inspector, the situation would get worse because I would be required to create corresponding interfaces such as OperationPerfStatsImpl. The standard MBeans convention would make the interfaces depend on the implementations and represents a needless duplication of the inheritance hierarchy for this system.

The rest of the aspect is responsible for creating the right MBean and object name with JMX. I reuse a JMX utility from the Spring framework, the InterfaceBasedMBeanInfoAssembler, which makes it easier to create a JMX DynamicMBean that manages my PerfStats instance using the PerfStatsMBean interface. At this stage, I've exposed only PerfStats implementations. This aspect also defines helper methods using inter-type declarations on managed bean classes. If a subclass of one of these classes needed to override the default behavior, it could do so by overriding the method.

You may be wondering why I've used an aspect for management rather than simply adding support directly into the PerfStatsImpl implementation class. While adding management to this one class wouldn't scatter my code, it would entangle the performance-monitoring system's implementation with JMX. So, if I wanted to use the system in an application without JMX, I would be forced to include the libraries and somehow disable the service. Moreover, as I expand the system's management functionality, I expect to expose more classes for management with JMX. Using aspects keeps the system's management policy modular.

Back to top

Database request monitoring

Distributed calls are a common source of slow application performance and errors. Most Web-based applications do a significant amount of database work, making monitoring queries and other database requests an especially important area for performance monitoring. Common issues include ill-written queries, missing indexes, and excessive numbers of database requests per operation. In this section, I'll expand the monitoring system to track database activity, correlated with operations.

To start with, I'll monitor database connection times and the execution of database statements. To support this effectively, I need to generalize my performance monitoring information and allow for tracking performance nested within an operation. I'll want to extract the common elements of performance into an abstract base class. Each base class is responsible for tracking performance before and after certain operations and will need to update system-wide performance statistics for that information. This lets me track nested servlet requests and will be important to support tracking controllers in Web application frameworks (discussed in Part 2).

Because I want to update database performance by request, I'll use a composite pattern to track statistics held by other statistics. This way, statistics for operations (such as servlets) hold performance statistics for each database. The database statistics hold information about connection times and aggregate additional statistics for each individual statement. Figure 4 shows how the overall design fits together. Listing 4 has the new base monitoring aspect that supports monitoring different requests.

/** Base aspect for monitoring functionality. 
 *  Uses the worker object pattern.
 */
public abstract aspect AbstractRequestMonitor {

    /** Matches execution of the worker object
     *  for a monitored request.
     */
    public pointcut 
      requestExecution(RequestContext requestContext) :
        execution(* RequestContext.execute(..)) 
          && this(requestContext);
    
    /** In the control flow of a monitored request,
     *  i.e., of the execution of a worker object. 
     */
    public pointcut inRequest(RequestContext requestContext) :
        cflow(requestExecution(requestContext));

    /** establish parent relationships
     *  for request context objects.
     */ 
    // use of call is cleaner since constructors are called
    // once but executed many times
    after(RequestContext parentContext) 
      returning (RequestContext childContext) : 
      call(RequestContext+.new(..)) && 
        inRequest(parentContext) {
        childContext.setParent(parentContext);
    }

    public long getTime() {
        return System.currentTimeMillis();
    }

    /** Worker object that holds context information
     *  for a monitored request.
     */
    public abstract class RequestContext {
        /** Containing request context, if any. 
         *  Maintained by @link AbstractRequestMonitor
         */
        protected RequestContext parent = null;        
        /** Associated performance statistics. 
         *  Used to cache results of @link #lookupStats()
         */
        protected PerfStats stats;
        /** Start time for monitored request. */ 
        protected long startTime;

        /** 
         * Record execution and elapsed time 
         * for each monitored request.
         * Relies on @link #doExecute() to proceed
         * with original request. 
         */
        public final Object execute() {
            startTime = getTime();
            
            Object result = doExecute();
            
            PerfStats stats = getStats();
            if (stats != null) {
                stats.recordExecution(startTime, getTime());
            }
            
            return result;
        }
        
        /** template method: proceed with original request */
        public abstract Object doExecute();

        /** template method: determines appropriate performance
         *  statistics for this request 
         */
        protected abstract PerfStats lookupStats();
        
        /** returns performance statistics for this method */ 
        public PerfStats getStats() {
            if (stats == null) {
                stats = lookupStats(); // get from cache if available
            }
            return stats;
        }

        public RequestContext getParent() {
            return parent;            
        }
        
        public void setParent(RequestContext parent) {
            this.parent = parent;            
        }
    }
}

As you might expect, I had a number of choices for how to store the shared performance statistics and per-request state for the base monitoring aspect. For example, I could have used a singleton with lower-level mechanisms like a ThreadLocal holding a stack of statistics and context. Instead, I chose to use the Worker Object pattern (see Resources), which allows for a more modular, concise expression. While this imposes a bit of extra overhead, the additional time required to allocate a single object and execute the advice is generally negligible compared to the time servicing Web and database requests. In other words, I can do some processing work in the monitoring code without adding overhead because it runs only relatively infrequently and generally is dwarfed by the time spent sending information over networks and waiting for disk I/O. This would be a bad design for a profiler, where you would want to track data about many operations (and methods) per request. However, I'm summarizing statistics about requests, so the choice is a reasonable one.

In the above base aspect, I've stored transient state about the currently monitored request in an anonymous inner class. This worker object is used to wrap any execution of monitored requests. The worker object, a RequestContext, is defined in the base class and provides a final execute method that defines the flow for monitoring any request. The execute method delegates to an abstract template method, doExecute(), which is responsible for proceeding with the original join point. The doExecute() method also acts as a natural point to set up statistics before proceeding with the monitored join point based on context information, such as the data source being connected to, and to associate returned values such as database connections after returning from the join point.

Each monitor aspect is also responsible for providing an implementation of an abstract method, lookupStats(), to determine what statistics object is updated for a given request. lookupStats() needs to access information based on the monitored join point. In general, the context captured must vary in each monitoring aspect. For example, in HttpServletMonitor, the context needed is the class of the currently executing operation object. For a JDBC connection, the context needed is the data source being acquired. Because the requirements will differ according to context, the advice to set up the worker object is best contained in each sub-aspect rather than in the abstract base aspect. This arrangement is cleaner, it allows type checking, and it performs better than writing one piece of advice in the base class that passes the JoinPoint to all the children.

Back to top

Servlet request tracking

The AbstractRequestMonitor does contain one concrete after advice to track the parent contexts of request contexts. This allows me to associate the operation statistics for nested requests with the statistics of their parents (for example, what servlet request caused this database access). For my monitoring example system, I explicitly do want nested worker objects and do not limit myself to handling just top-level requests. For example, all the Duke's Bookstore Servlets call a BannerServlet as part of rendering a page. It is useful that I can break out the times for these calls separately, as Listing 5 shows. I don't show the supporting code for looking up nested statistics in an operation statistics here (you can see it in the article source code). In part two, I'll revisit this topic to show how I update the JMX support to display nested statistics like this.

Listing 5 should now read
public aspect HttpServletMonitor extends AbstractRequestMonitor {  

  /** Monitor Servlet requests using the worker object pattern */
  Object around(final Object operation) : 
    monitoredOperation(operation) {
      RequestContext requestContext = new RequestContext() {
          public Object doExecute() {
              return proceed(operation);
          }
          
          public PerfStats lookupStats() {                
              if (getParent() != null) {
                  // nested operation
                  OperationStats parentStats =
(OperationStats)getParent().getStats();
                  return
parentStats.getOperationStats(operation.getClass());
              }
              return lookupStats(operation.getClass());
          }
        };
        return requestContext.execute();
    }
 ...
 

Listing 5 shows the revised monitoring advice for servlet request tracking. All the rest of the code remains the same as in Listing 1: it is either pulled up into the base AbstractRequestMonitor aspect or remains the same.

Back to top

JDBC monitoring

Having set up my performance monitoring framework, I am now ready to track database connection times and the time for database statements. Moreover, I want to be able to correlate database statements with the actual database I have connected to (in the lookupStats() method). To do this, I create two aspects to track information about JDBC statements and connections: JdbcConnectionMonitor and JdbcStatementMonitor.

One of the key responsibilities for these aspects is to follow chains of object references. I would like to track requests by the URL I used to connect to the database, or at least the database name. This requires me to track the data source used to acquire a connection. I would further like to track performance of prepared statements by the SQL strings that was prepared prior to executing to them. Finally, I need to track the JDBC connection associated with statements that are executing. You'll note that JDBC statements do provide an accessor for their connection; however, application servers and Web application frameworks frequently use the decorator pattern to wrap JDBC connections. I want to make sure I can correlate statements with the connection I have a handle to and not a wrapped connection.

The JdbcConnectionMonitor is responsible for measuring performance statistics for connections to the database, and it also associates connections with their metadata (for example, a JDBC URL or a database name) from data sources or connection URLs. The JdbcStatementMonitor is responsible for measuring performance statistics for executing statements, tracks the connections used to acquire statements, and tracks the SQL strings associated with prepared (and callable) statements. Listing 6 shows the JdbcConnectionMonitor aspect.

/** 
 * Monitor performance for JDBC connections, 
 * and track database connection information associated with them. 
 */ 
public aspect JdbcConnectionMonitor extends AbstractRequestMonitor {
    
    /** A call to establish a connection using a 
     *  <code>DataSource</code> 
     */
    public pointcut dataSourceConnectionCall(DataSource dataSource) : 
        call(Connection+ DataSource.getConnection(..)) 
          && target(dataSource);

    /** A call to establish a connection using a URL string */
    public pointcut directConnectionCall(String url) :
        (call(Connection+ Driver.connect(..))  || call(Connection+ 
          DriverManager.getConnection(..))) && 
        args(url, ..);

    /** A database connection call nested beneath another one
     *  (common with proxies).
     */    
    public pointcut nestedConnectionCall() : 
        cflowbelow(dataSourceConnectionCall(*) || 
          directConnectionCall(*));
    
    /** Monitor data source connections using
     *  the worker object pattern 
     */
    Connection around(final DataSource dataSource) : 
      dataSourceConnectionCall(dataSource) 
        && !nestedConnectionCall() {
        RequestContext requestContext = 
          new ConnectionRequestContext() {
            public Object doExecute() {                
                accessingConnection(dataSource); 
                // set up stats early in case needed

                Connection connection = proceed(dataSource);

                return addConnection(connection);
            }
            
        };
        return (Connection)requestContext.execute();
    }

    /** Monitor url connections using the worker object pattern */
    Connection around(final String url) : directConnectionCall(url) 
      && !nestedConnectionCall() {
        RequestContext requestContext = 
          new ConnectionRequestContext() {
            public Object doExecute() {
                accessingConnection(url);

                Connection connection = proceed(url);
                
                return addConnection(connection);
            }
        };
        return (Connection)requestContext.execute();
    }

    /** Get stored name associated with this data source. */ 
    public String getDatabaseName(Connection connection) {
        synchronized (connections) {
            return (String)connections.get(connection);
        }
    }

    /** Use common accessors to return meaningful name
     *  for the resource accessed by this data source.
     */
    public String getNameForDataSource(DataSource ds) {
        // methods used to get names are listed in descending
        // preference order 
        String possibleNames[] = 
          { "getDatabaseName", 
              "getDatabasename", 
              "getUrl", "getURL", 
              "getDataSourceName", 
              "getDescription" };
        String name = null;
        for (int i=0; name == null && 
          i<possibleNames.length; i++) {
            try {            
                Method method = 
                  ds.getClass().getMethod(possibleNames[i], null);
                name = (String)method.invoke(ds, null);
            } catch (Exception e) {
                // keep trying
            }
        }
        return (name != null) ? name : "unknown";
    }    

    /** Holds JDBC connection-specific context information:
     *  a database name and statistics
     */
    protected abstract class ConnectionRequestContext
      extends RequestContext {
        private ResourceStats dbStats;
        
        /** set up context statistics for accessing
         *  this data source
         */ 
        protected void 
          accessingConnection(final DataSource dataSource) {
            addConnection(getNameForDataSource(dataSource), 
              connection);
        }
        
        /** set up context statistics for accessing this database */ 
        protected void accessingConnection(String databaseName) {
            this.databaseName = databaseName;

            // might be null if there is database access
            // caused from a request I'm not tracking...
            if (getParent() != null) {
                OperationStats opStats = 
                  (OperationStats)getParent().getStats();
                dbStats = opStats.getDatabaseStats(databaseName);
            }
        }

        /** record the database name for this database connection */ 
        protected Connection 
          addConnection(final Connection connection) {
            synchronized(connections) {
                connections.put(connection, databaseName);
            }
            return connection;
        }

        protected PerfStats lookupStats() {
            return dbStats;
        }
    };    

    /** Associates connections with their database names */    
    private Map/*<Connection,String>*/ connections = 
      new WeakIdentityHashMap();

}

Listing 6 shows my aspect for tracking database connections using AspectJ and the JDBC API. It has a map to associate database names with each JDBC connection.

Inside jdbcConnectionMonitor

Inside the JdbcConnectionMonitor shown in Listing 6, I've defined pointcuts to capture two different ways of connecting to a database: through a data source or directly through a JDBC URL. The connection monitor contains monitoring advice for each case, both of which set up a worker object. The doExecute() methods start by proceeding with the original connection and then pass the returned connection to one of two helper methods named addConnection. In both cases, the pointcut being advised excludes connection calls that result from another connection (for example, if connecting to a data source results in establishing a JDBC connection).

The addConnection() for data sources delegates to a helper method, getNameForDataSource(), to try to determine the name of a database from the data source. The DataSource interface doesn't provide any such mechanism, but almost every implementation provides a getDatabaseName() method. getNameForDataSource() uses reflection to try this and a few other common (and less common) methods that provide a useful identifier for a data source. This addConnection() method then delegates to the addConnection() method that takes a string for a name.

The delegated addConnection() method retrieves the operational statistics from its parent-request context and looks up database statistics based on the database name (or other description string) associated with the given connection. It then stores that information in the dbStats field on the request-context object to update performance information about acquiring the connection. This lets me track the time required to connect to the database (often this is really the time required to get a connection from a pool). The addConnection() method also updates the connections map of connections to database names. This map is used subsequently when JDBC statements are executed to update statistics for the appropriate request. The JdbcConnectionMonitor also provides a helper method, getDatabaseName(), which looks up the string name for a connection from the connections map.

Weak identity maps and aspects

The JDBC monitoring aspects use weak identity hash maps. These maps hold weak references to allow tracked objects like connections to be garbage collected when they are referenced only by the aspect. This is important because the singleton aspects are typically not garbage collected. If the references weren't weak, the application would have a memory leak. The aspects use identity maps to avoid calling the hashCode or equals methods on connections or statements. This is important because I want to track the connections and statements regardless of their state: I don't want to encounter exceptions from the hashCode method, nor should I rely on the hash code of the object remaining the same when its internal state changes (for example, when closed). I experienced this issue when working with dynamic proxy-based JDBC objects (like those from iBatis), which threw exceptions when any method on them was called after a connection had closed. This led to errors in trying to record statistics after finishing an operation.

One lesson to learn from this is to minimize the assumptions you make about third-party code. Using identity maps is a good way to avoid making assumptions about the implementation logic in advised code. In this case, I'm using an open source implementation of a WeakIdentityHashMap from the Emory DCL Java Utilities (see Resources). Tracking metadata information about connections or statements lets me group statistics across each request for equivalent connections or statements. This means I can track based on just object instances; I don't need to use object equality to track these JDBC objects. Another lesson to keep in mind is that JDBC objects are frequently wrapped by decorators (increasingly with dynamic proxies) by various frameworks. It's a bad idea to assume that you're working with a simple, raw implementation of such an interface!

Inside jdbcStatementMonitor

Listing 7 shows the JdbcStatementMonitor aspect. This aspect has two primary responsibilities: tracking information about creating and preparing statements and then monitoring performance statistics for executing JDBC statements.

/**
 * Monitor performance for executing JDBC statements, 
 * and track the connections used to create them, 
 * and the SQL used to prepare them (if appropriate).
 */
public aspect JdbcStatementMonitor extends AbstractRequestMonitor {
    
    /** Matches any execution of a JDBC statement */
    public pointcut statementExec(Statement statement) : 
        call(* java.sql..*.execute*(..)) && 
          target(statement);
    
    /**
     * Store the sanitized SQL for dynamic statements. 
     */
    before(Statement statement, String sql, 
      RequestContext parentContext): 
      statementExec(statement) && args(sql, ..) 
        && inRequest(parentContext) {
        sql = stripAfterWhere(sql);
        setUpStatement(statement, sql, parentContext);
    }
    
    /** Monitor performance for executing a JDBC statement. */ 
   Object around(final Statement statement) : 
     statementExec(statement) {
        RequestContext requestContext = 
          new StatementRequestContext() {
            public Object doExecute() {
                return proceed(statement);
            }
        };
        return requestContext.execute();
    }
       
    /**
     * Call to create a Statement.
     * @param connection the connection called to
     * create the statement, which is bound to 
     * track the statement's origin 
     */
    public pointcut callCreateStatement(Connection connection):
        call(Statement+ Connection.*(..)) 
          && target(connection);

    /**
     * Track origin of statements, to properly 
     * associate statistics even in
     * the presence of wrapped connections 
     */
    after(Connection connection) returning (Statement statement):
      callCreateStatement(connection) {
        synchronized (JdbcStatementMonitor.this) {
            statementCreators.put(statement, connection);
        }
    }

    /** 
     * A call to prepare a statement.
     * @param sql The SQL string prepared by the statement. 
     */
    public pointcut callCreatePreparedStatement(String sql):
        call(PreparedStatement+ Connection.*(String, ..)) 
          && args(sql, ..);

    /** Track SQL used to prepare a prepared statement */
    after(String sql) returning (PreparedStatement statement): 
      callCreatePreparedStatement(sql) {
        setUpStatement(statement, sql);
    }
            
    protected abstract class StatementRequestContext 
      extends RequestContext {
        /** 
         * Find statistics for this statement, looking for its 
         * SQL string in the parent request's statistics context 
         */
        protected PerfStats lookupStats() {
            if (getParent() != null) {
                Connection connection = null;
                String sql = null;

                synchronized (JdbcStatementMonitor.this) {
                    connection = 
                      (Connection) statementCreators.get(statement);
                    sql = (String) statementSql.get(statement);
                }

                if (connection != null) {
                    String databaseName = 
                      JdbcConnectionMonitor.aspectOf().
                        getDatabaseName(connection);
                    if (databaseName != null && sql != null) {
                        OperationStats opStats = 
                          (OperationStats) getParent().getStats();
                        if (opStats != null) {
                            ResourceStats dbStats = 
                              opStats.getDatabaseStats(databaseName);

                            return dbStats.getRequestStats(sql);
                        }
                    }
                }
            }
            return null;
        }
    }

    /** 
     * To group sensibly and to avoid recording sensitive data,
     * I don't record the where clause (only used for dynamic
     * SQL since parameters aren't included
     * in prepared statements)
     * @return subset of passed SQL up to the where clause
     */
    public static String stripAfterWhere(String sql) {
        for (int i=0; i<sql.length()-4; i++) {
            if (sql.charAt(i)=='w' || sql.charAt(i)==
              'W') {
                if (sql.substring(i+1, i+5).equalsIgnoreCase(
                  "here"))
                  {
                    sql = sql.substring(0, i);
                }
            }
        }
        return sql;
    }    

    private synchronized void 
      setUpStatement(Statement statement, String sql) {
        statementSql.put(statement, sql);
    }

    /** associate statements with the connections
     *  called to create them
     */
    private Map/*<Statement,Connection>*/ statementCreators = 
      new WeakIdentityHashMap();

    /** associate statements with the
     *  underlying string they execute
     */
    private Map/*<Statement,String>*/ statementSql = 
      new WeakIdentityHashMap();
}

The JdbcStatementMonitor maintains two weak identity maps: statementCreators and statementSql. The first tracks the connections used to create a statement. As I noted earlier, I don't want to rely on the getConnection method of the statement because it could refer to a wrapped connection for which I don't have metadata. Note the callCreateStatement pointcut, which I advise to monitoring JDBC statement execution. This matches any call to a method defined on a JDBC connection that returns a Statement or any subclass thereof. This matches the 12 different ways that a statement can be created or prepared in JDBC and is designed to adapt to future extensions to the JDBC API.

The statementSql map tracks the SQL strings being executed by a given statement. This is updated in two different ways. When creating a prepared statement (including a callable statement), the SQL string argument is captured at creation time. For dynamic SQL statements, the SQL string argument is captured from the statement execution call before the monitoring advice uses it. (Advice precedence doesn't matter here; the string is captured before the execution occurs, whereas it's used to look up statistics after execution has completed.)

Performance monitoring for statements is handled by a single around advice that sets up a worker object whenever a JDBC statement is executed. The statementExec pointcut for executing a JDBC statement captures any call to a method whose name starts with execute on any instance of a JDBC Statement (including subclasses), where the method is defined in the JDBC API (that is, in any package whose name starts with java.sql).

The lookupStats() method in the worker object uses the parent (servlet) statistics context to look up the database statistics for the given connection and then looks up the JDBC statement statistics for the given SQL string. The direct statement execution method includes additional logic to strip the data after the where clause in the SQL statement. This avoids the risk of exposing sensitive data and it also allows common statements to be grouped. A more sophisticated approach would just strip query parameters. However, most applications use prepared statements rather than dynamic SQL statements, so I won't delve into this.

Back to top

Tracking JDBC information

Before I wrap up, let's think for a minute about how the monitor aspects resolve the challenges of tracking JDBC information. The JdbcConnectionMonitor lets me associate a text description of a database (such as a JDBC URL) with the connection being used to access a database. Likewise, the statementSql mapping in JdbcStatementMonitor tracks the SQL strings used even for prepared statements, ensuring that I can group the queries being executed into meaningful buckets, with sensible names. And finally, the statementCreators mapping in JdbcStatementMonitor lets me correlate statements with the connection I have a handle to, and not a wrapped connection. This approach to coordinating multiple advices that update internal state is frequently useful when applying aspects to real world problems. In many cases, you need to track context information from a sequence of join points, which can't be captured in a single AspectJ pointcut that exposes context. When this is the case, this technique of tracking state from one join point to be used in a later one is quite helpful.

With this information all available, the JdbcStatementMonitor is able to monitor performance fairly naturally. The actual advice on the statement execution pointcut just follows the standard method of creating a worker object that proceeds with the original computation. The lookupStats() method uses the three different mappings to look up the connection and the SQL associated with this statement. It then uses its parent request to find the right database statistics based on the connection's description, and to find statement statistics based on the SQL key string. lookupStats() is defensive, in that it checks for null values in case application programs violate any expectations about use. In the second half of this article, I'll show you how to use AOP to systematically ensure that monitoring code doesn't cause problems in the monitored application.

Back to top

Conclusion to Part 1

Thus far, I've built up a core monitoring infrastructure that can systematically track application performance and measure database activity within a Servlet operation. The monitoring code then plugs naturally into the JMX interface to expose the results, as Figure 5 illustrates. The code can already monitor significant application logic, and you have already seen how much easier it is to extend and update the monitoring approach.

While the code presented here is fairly straightforward, it's a big change from the traditional approach. AspectJ's modular approach let me handle monitoring functions concisely and consistently. This is a major improvement over scattering calls to update statistics and to track context throughout my example application. Even using objects to encapsulate statistics tracking, the traditional approach would require multiple calls for every user operation and every access to a resource. Such consistency would be tedious and quite difficult to implement once, let alone maintain.

In the second part of this article, I'll emphasize the pragmatic issues in developing and deploying an AOP-based system for performance monitoring. I'll show you how to use AspectJ 5 load-time weaving to monitor multiple applications running in Apache Tomcat, including monitoring inside third-party libraries. I'll show you how to measure the overhead of monitoring, how to selectively enable monitoring at run time, and how to measure the performance and memory impact of load-time weaving. I also will show how to use aspects to prevent errors in monitoring code from causing application errors. Finally, I'll extend the Glassbox Inspector to support Web services and common Web application frameworks like Struts and Spring and to track application errors. Stay tuned!

Acknowledgments

Thanks to Ramnivas Laddad, Will Edwards, Matt Hutton, David Pickering, Rob Harrop, Alex Vasseur, Paul Sutter, Mik Kersten, and Eugene Kuleshov for reviewing this article and giving such insightful comments.

Back to top

Download

Information about download methods

Resources

Learn

• "Enhance design patterns with AspectJ, Part 2" (Nicholas Lesiecki, developerWorks, May 2005): Describes the AspectJ Marker Interface idiom.
  
  
• "Secrets of lightweight development success" (Bruce Tate, developerWorks, May 2005): Summarizes dependency injection and the use of IOC containers.
  
  
• AspectJ in Action (Ramnivas Laddad, Manning Publications, 2003): Describes in detail the Worker Object pattern.
  
  
• The Aspects Blog (Adrian Colyer): Discusses using AspectJ with the Spring framework.
  
  
• The J2EE 1.4 tutorial: Source of the Duke's Bookstore example.
  
  
• AOP@Work: Incorporate AOP into your day-to-day Java programming.
  
  

Get products and technologies

• Glassbox Inspector: An open source project hosted on Java.net.
  
  
• WeakIdentityHashMap: Part of the open source Emory DCL Java Utilities.
  
  
• AspectJ home page: Learn more about AspectJ.
  
  
• JMX home page: Download JMX and the JMX Remote reference implementations.
  
  

Discuss

• developerWorks blogs: Get involved in the developerWorks community.
  
  

About the author

Comments

Back to top

Trademarks  |  My developerWorks terms and conditions

Table of contents

• The basic system
• Exposing performance data
• Database request monitoring
• Servlet request tracking
• JDBC monitoring
• Tracking JDBC information
• Conclusion to Part 1
• Download
• Resources
• About the author
• Comments

Next steps from IBM

Spring, JRuby, and Ajax development is easier with WebSphere Application Server - a smart Java 5 and J2EE Web services-based application server.

---

• Try: The no-charge WebSphere Application Server Community Edition is a pre-integrated, lightweight Java 5 application server built on Apache Tomcat and other best-of-breed open source software such as OpenEJB, Apache Axis, and Apache Derby.
• Article: The article leverage the Spring Framework and the WebSphere Application Server to improve your J2EE project productivity.
• Tutorial: See how the free WebSphere Application Server and XML can improve the efficiency of your JRuby on Rails and Ajax development.
• Buy: WebSphere Application Server - Express

My developerWorks community

Dig deeper into Java on developerWorks

Rate a product. Write a review.

Write a review for Rational products today!

Special offers