[펌] AOP@Work: Performance monitoring with AspectJ, Part 1

A look inside the Glassbox Inspector with AspectJ and JMX

 

Level: Intermediate

Ron Bodkin (ron.bodkin@newaspects.com), Founder, New Aspects of Software

13 Sep 2005

Say goodbye to scattered and tangled monitoring code, as Ron Bodkin shows you how to combine AspectJ and JMX for a flexible, modular approach to performance monitoring. In this first of two parts, Ron uses source code and ideas from the Glassbox Inspector open source project to help you build a monitoring system that provides correlated information to identify specific problems, but with low enough overhead to be used in production environments.

About this series The AOP@Work series is intended for developers who have some background in aspect-oriented programming and want to expand or deepen what they know. As with most developerWorks articles, the series is highly practical: you can expect to come away from every article with new knowledge that you can put immediately to use. Each of the authors contributing to the series has been selected for his leadership or expertise in aspect-oriented programming. Many of the authors are contributors to the projects or tools covered in the series. Each article is subjected to a peer review to ensure the fairness and accuracy of the views expressed. Please contact the authors individually with comments or questions about their articles. To comment on the series as a whole, you may contact series lead Nicholas Lesiecki. See Resources for more background on AOP.

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 1. Glassbox Inspector with a JConsole JMX client

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.

Figure 2. The Glassbox Inspector architecture

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:

Listing 1. An aspect for capturing time and counts of servlets

/** * 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().

Managing overhead I'll focus on techniques to manage the monitoring framework's overhead in the second half of the article, but for now, it's worth noting the basic strategy: I'll do some in-memory operations that take up to a few microseconds when something slow happens (like accessing a servlet or database). In practice, this adds negligible overhead to the end-to-end response time of most applications.

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

Thread safety The statistics-capturing code for the Glassbox Inspector monitoring system isn't thread safe. I prefer to maintain (potentially) slightly inaccurate statistics in the wake of rare simultaneous access to a PerfStats instance by multiple threads, rather than adding extra synchronization to program execution. If you prefer improved accuracy, you can simply make the mutators synchronized (for example, with an aspect). Synchronization would be important if you were tracking accumulated times more than 32 bits long, since the Java platform doesn't guarantee atomic updates to 64-bit data. However, with millisecond precision, this would give you 46 days of accumulated time. I recommend aggregating and resetting statistics far more frequently for any real use, so I've stuck with the int values.

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.

Figure 3. Using Glassbox Inspector to view operation statistics

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.

Listing 2. Implementing the JMX management feature

/** 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; }}

JMX tools Several good JMX implementation libraries support remote JMX. Sun Microsystems provides reference implementations of JMX and JMX Remote under a free license. Some open source implementations also exist. MX4J is a popular one that includes helper libraries and tools like a JMX client. Java 5 integrates JMX and JMX remote support into the virtual machine. Java 5 also introduced management beans for VM performance in the javax.management package. Sun's Java 5 virtual machines include the standard JMX client JConsole.

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.

Listing 3. Exposing beans for JMX management

/** 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.

Deploying these aspects The aspects used in this article need to be applied only to each application they are monitoring, not to third-party libraries or container code. As such, you could integrate them into a production system by compiling them into an application, by weaving into an already compiled application, or by using load-time weaving, which I prefer for this use case. You'll learn more about load-time weaving in the second half of this article.

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.

Distributed calls In this section, I present an approach to handling distributed calls to a database. While databases are typically hosted on a different machine, my technique also works for a local database. My approach also extends naturally to other distributed resources, including remote object invocations. In the second part of the article, I'll show you how to apply this technique to Web services invocations using SOAP.

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.

Figure 4. Generalized monitoring design


Listing 4. The base monitoring aspect

/** 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. Updated servlet monitoring

Listing 5 should now readpublic 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(); returnparentStats.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.

Listing 6. 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.

Listing 7. The JdbcStatementMonitor aspect

/** * 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