ONJava.com    
 Published on ONJava.com (http://www.onjava.com/)
 See this if you're having trouble printing code examples


Performance Analysis of J2EE Applications Using AOP Techniques Performance Analysis of J2EE Applications Using AOP Techniques

by Ramchandar Krishnamurthy
05/12/2004

In a complex distributed computing environment like J2EE, it is very difficult to pinpoint the component that is causing a performance bottleneck. Applications can be profiled by including instrumentation code manually, but this could be cumbersome and time-consuming, and might impact the stability of the application itself. Aspect-Oriented Programming (AOP) technology can be elegantly and effectively applied for performance analysis, as illustrated by Davies et al.

Aspect-oriented programming allows the programmer to inject pieces of functionality into existing code. This can be done either during compile time (AspectJ) or during run time (Aspectwerkz). The functionality that is injected typically addresses cross-cutting concerns spread among existing code pieces. In AOP terminology, such functionality that can be injected into existing code is termed an advice. The point of execution in the existing code where the advice needs to be applied is termed a point-cut. The point-cut together with an advice is termed as an aspect. For more information on AOP, refer to Graham O'Regan's ONJava article "Introduction to Aspect-Oriented Programming."

In this article we demonstrate the use of AOP techniques through which J2EE applications can be easily instrumented without any modifications to application code. We have developed a very simple tool to achieve the above objective. Since the instrumentation has very low overhead, this tool can be deployed in the staging environments to identify problematic Java method calls and SQL statements.

We describe the architecture of the profiling tool and then the advices that were developed to instrument the application. This is followed by an illustration of how the instrumentation can be added to the necessary method calls through point-cuts, and finally, we show some of the results obtained through this tool.

Architecture

The architecture of the system is shown in Figure 1 and detailed in the following sections.

Figure 1
Figure 1. Architecture of AOP Profiler

AOP Infrastructure

We considered both AspectJ and Aspectwerkz for providing the AOP infrastructure and chose Aspectwerkz, since it does not require the J2EE application to be re-compiled. Due to this capability, we can profile an existing J2EE application without any additional development activity. But we also noticed that Aspectwerkz introduces a tiny overhead as compared to AspectJ; this is due to reflection (java.lang.reflect.Method.invoke()) used by Aspectwerkz to incorporate the advices into the application code. By defining the point-cuts in a simple XML file, Aspectwerkz makes it much easier in our situation to decide which methods need to be profiled.

Related Reading

J2EE Design Patterns
By William Crawford, Jonathan Kaplan

Agent-Server Architecture

To reduce the overhead on the application that is being profiled, we use a agent-server architecture. The aspects incorporate lightweight code that captures the timing information and then transmits this information to a server which is expected to run on a different machine on the network. The server parses this information and stores this information in a MySQL database. Since all of the profiling information is in a database, we can write different kinds of SQL queries to view the profiling data from different angles. For example, with a simple group by with an avg function, we can get the average method execution times of all the methods. We can sort this list using order by to pinpoint the most expensive method.

Capturing CPU Time

While it is easy to capture the elapsed time using System.currentTimeMillis(), this measure is not accurate in all situations, especially if there are contentions. The CPU time is a more accurate measure of the execution time of a method. We capture the CPU time using the JVM Profiler Interface (JVMPI). Please refer to "Using JVM Profiler Interface for Accurate Timing," by Jesper Gortz, for more information.

Capturing SQL Execution Time

Most J2EE applications are data-centric and typically persist data in relational databases. A critical aspect of performance analysis of a J2EE application would therefore rely on the timing information of the SQLs fired from the J2EE application. We have managed to capture this information by utilizing the P6Log driver. This piece of software acts as a layer between the J2EE connection pool and the actual JDBC driver and captures the timing information of the SQLs fired. We apply aspects to this software to retrieve that information.

Capturing the Sequence of Method Execution

Apart from obtaining the individual method execution times, it is also helpful to observe the control flow in the container to fulfill a request. We capture the flow of information using ThreadLocal variables. The ThreadLocal variable holds a unique ID for each request, along with a sequence number that runs in the order of the method execution. The limitation in this implementation is that the sequence can be captured meaningfully only when all of the components that are to be profiled are executed in the same JVM; i.e., there are no remote calls. A servlet filter is utilized to trap all requests and an aspect is applied to the filter method to initialize the ThreadLocal variable with a new request ID and a sequence starting from 0.

Using Advices to Capture Performance Data

In this section, we describe the three different advices we use to capture performance metrics from a J2EE application. The first advice is used to capture the sequence of method execution, the second one captures the performance metrics of Java method execution, and the third one captures the SQL execution times. These classes and some supporting code are available in the source code link at the bottom of the article.

StartRequest Advice

This advice is used to capture the sequence of method execution. This advice typically should be applied in the entry point of the particular layer of the J2EE application. In a web layer, it can either be applied to the main controller servlet (if MVC is implemented), or to a servlet filter that filters all requests to the web layer. This advice sets a new request ID to the ThreadLocal variable and resets the sequence count to 0.

package com.infosys.setlabs.j2ee.performance.instrumentation;

import org.codehaus.aspectwerkz.joinpoint.JoinPoint;
import org.codehaus.aspectwerkz.joinpoint.MethodJoinPoint;
import org.codehaus.aspectwerkz.xmldef.advice.AroundAdvice;

public class StartRequestAdvice 
                  extends AroundAdvice {
  public Object execute(final JoinPoint joinPoint)
   throws Throwable {

    InstrumentationHelper threadLocal = 
      InstrumentationHelper.getHolder();
    StringBuffer b = new StringBuffer();
/* Adding a Unique ID, a string with current 
   time and a running number */
    b.append("REQUEST-");
    b.append(System.currentTimeMillis());
    b.append("-");
    b.append(InstrumentationHelper.nextIdVal());
    threadLocal.setId(b.toString());
// Initialize the method execution sequence to 0
    threadLocal.setSequence(0);
    final Object result = joinPoint.proceed();    
    return result;
  }
}

InstrumentJava Advice

This advice is to be applied to all Java method calls that need to be instrumented. This advice captures the time stamps and memory consumption before and after the method call and transmits this information to the InstrumentationServer. This is the main advice for profiling J2EE applications.

Two entries are made to the profiling database: one with the start time stamp of the method, and one when the method has completed.

package com.infosys.setlabs.j2ee.performance.instrumentation;

import org.codehaus.aspectwerkz.xmldef.advice.AroundAdvice;
import org.codehaus.aspectwerkz.joinpoint.JoinPoint;
import org.codehaus.aspectwerkz.joinpoint.MethodJoinPoint;

import com.infosys.setlabs.j2ee.performance.instrumentation.cpuprofiler.InfosysProfiler;

public class InstrumentJavaAdvice 
                 extends AroundAdvice { 
  
  public Object execute(final JoinPoint joinPoint) 
                 throws Throwable {

    long time = 0;
    long cpuTime = 0;
    long memory = 0;
    Runtime rt = Runtime.getRuntime();

/* Get the fully classified name of the method 
   that is being profiled */
    MethodJoinPoint jp = 
       (MethodJoinPoint)joinPoint;
    StringBuffer name_buf = new StringBuffer();
    name_buf.append(
       jp.getTargetClass().getName());
    name_buf.append(".");
    name_buf.append(jp.getMethodName());
    final String name = name_buf.toString();
    
    StringBuffer toPrint_buf = new StringBuffer();

/* Register the time stamps and memory BEFORE 
   method execution */
    time = System.currentTimeMillis();
    cpuTime = 
       InfosysProfiler.getCurrentThreadCpuTime();
    memory = rt.freeMemory();
    
/* Get the next number in the sequence of method
   executions */
    int sequence = 
       InstrumentationHelper.nextSequence();

    toPrint_buf.append(
       InstrumentationHelper.getString("JAVA",
                       sequence, name, "START", 
                       time, cpuTime, 
                       0, 0, memory));
 
// Execute the method
    final Object result = joinPoint.proceed();    
 
/* Register the time stamps and memory AFTER 
   method execution */
    long new_time = System.currentTimeMillis();
    long new_cpuTime = 
       InfosysProfiler.getCurrentThreadCpuTime();
    long new_memory = rt.freeMemory();

    toPrint_buf.append("\n");
    toPrint_buf.append(
      
      InstrumentationHelper.getString("JAVA",
                            sequence,name, 
                            "STOP", new_time, 
                            new_cpuTime, 
                            new_time-time, 
                            new_cpuTime-cpuTime, 
                            memory-new_memory));     
    
/* Send the information to the Instrumentation 
   Server */
    InstrumentationHelper.print(
        toPrint_buf.toString());
   
    return result;
	}  
}

The capturing of memory consumption using Runtime.freeMemory() is a quick-shot approach and is not always accurate. Instrumentation data with negative memory consumption figures indicates that garbage collection kicked off during the method execution. Such figures should not be considered for analysis of memory consumption.

InstrumentSQL Advice

This advice is to be applied on the P6Log methods to extract the SQL timing information. It extracts the parameters from the com.p6spy.engine.common.P6LogQuery.doLogElapsed method. This method contains the actual SQL statement that was fired and also the elapsed time for the SQL statement. The advice transmits this information to the Instrumentation Server.

package com.infosys.setlabs.j2ee.performance.instrumentation;

import org.codehaus.aspectwerkz.xmldef.advice.AroundAdvice;
import org.codehaus.aspectwerkz.joinpoint.JoinPoint;
import org.codehaus.aspectwerkz.joinpoint.MethodJoinPoint;

public class InstrumentSQLAdvice 
   extends AroundAdvice {
   public Object execute(JoinPoint joinPoint) 
      throws Throwable {
    
      MethodJoinPoint jp = 
       (MethodJoinPoint)joinPoint;
      Object[] params = jp.getParameters();

// SQL Start time
      long start = 
         ((Long)params[1]).longValue(); 

// SQL End time
      long end = 
         ((Long)params[2]).longValue();
      StringBuffer buf = 
         new StringBuffer();

// SQL Statement Type
      buf.append((String)params[3]);
      buf.append("-");

// The SQL String
      String sql = (String)params[5];

/* Clean the SQL string for null values, carriage 
   returns and single quotes */
      if (sql == null || sql.equals("")) {
         sql = "NULL";
      }
      buf.append(
         sql.replace('\n',' ').
             replace('\'','+'));
      InstrumentationHelper.print(
         InstrumentationHelper.getString("SQL",
            InstrumentationHelper.nextSequence(), 
            buf.toString(),"STOP",end,0,end-start,
            0, 0));    
      final Object result = joinPoint.proceed();
      return result;
   }
}

Instrumentation Helper

This is a simple helper class that assists the above advices. It does the following:

Using Point-cuts to Instrument the Application

The advices are defined the Aspectwerkz XML file as below:

<advice-def 
   name="javaLog" 
   class="com.infosys.setlabs.j2ee.performance.instrumentation.InstrumentJavaAdvice" 
   deployment-model="perJVM"
/>
<advice-def 
   name="sqlLog" 
   class="com.infosys.setlabs.j2ee.performance.instrumentation.InstrumentSQLAdvice"
   deployment-model="perJVM"
/>
<advice-def 
   name="startRequest"
   class="com.infosys.setlabs.j2ee.performance.instrumentation.StartRequestAdvice"
   deployment-model="perJVM"
/>

With the above three advices, it is now very easy to instrument any J2EE application to extract the performance data of specific methods. We specify the aspects in an XML document for Aspectwerkz. Aspectwerkz reads this document and applies the aspects to the point-cuts specified when the point-cut is loaded by the class loader.

The InstrumentSQLAdvice is applied to the P6Log method by specifying the point as below. The P6Spy driver captures all JDBC calls and logs them by calling the doLogElapsed method.

<aspect name="P6Spy">
   <pointcut-def 
      name="P6Spy" 
      type="method"
      pattern="* com.p6spy.engine.common.P6LogQuery.doLogElapsed(..)"
   />
   <bind-advice pointcut="P6Spy">
      <advice-ref name="sqlLog"/>
   </bind-advice>
</aspect>

J2EE containers are multi-threaded, and individual requests are handled by threads held in a thread pool. When a request is handled by the container, it is allotted to a thread and all of the calls for the request are executed serially in that thread. By applying the StartRequestAdvice to an appropriate method call, we can demarcate the requests. For example, we can apply this advice to a servlet filter that filters all request to the web layer.

<aspect name="request">
   <pointcut-def 
      name="request"
      type="method"
      pattern="* com.infosys.j2ee.cmptest.webfilter.WebFilter.doFilter(..)"
   />
   <bind-advice pointcut="request">
      <advice-ref name="startRequest"/>
   </bind-advice>
</aspect>

We can now use the InstrumentJavaAdvice to instrument the J2EE application and apply it to methods in which we are interested. Here, we show an example of how the Sun Java PetStore application can be instrumented to check which methods could be potential bottlenecks. The following aspects instrument all of the methods in the TemplateServlet class of PetStore and the GenericCatalogDAO class.

<aspect name="Catalog">
   <pointcut-def 
      name="DAOs" 
      type="method" 
      pattern="* com.sun.j2ee.blueprints.catalog.dao.GenericCatalogDAO.*(..)"
   />
   <bind-advice pointcut="DAOs">
      <advice-ref name="log"/>
   </bind-advice>
</aspect>
<aspect name="TemplateServlet">
   <pointcut-def
      name="EJBs"
      type="method"
      pattern="* com.sun.j2ee..TemplateServlet.*(..)"
   />
   <bind-advice pointcut="EJBs">
      <advice-ref name="log"/>
   </bind-advice>
</aspect>

Reporting and Analyzing the Profiling Data

The results of the instrumentation are stored in a MySQL database by the Instrumentation Server. Simple queries can retrieve the necessary information. For the above PetStore example, the following information was captured. This results display the sequence of method calls, the elapsed and CPU times in milliseconds, and the method/SQL that was executed.

Sequence Method/SQL Elapsed Time CPU Time
1 com.sun.j2ee.blueprints.waf.view.template.TemplateServlet.process 47 31.25
2 com.sun.j2ee.blueprints.waf.view.template.TemplateServlet.insertTemplate 47 31.25
3 com.sun.j2ee.blueprints.catalog.dao.GenericCatalogDAO.getProducts 16 0
4 statement-select a.productid, name, descn from product a, product_details b where a.productid = b.productid and locale = +en_US+ and a.catid = +DOGS+ order by name 16 0

The results indicate that the TemplateServlet.process() was called first. It in turn calls the TemplateServlet.insertTemplate(), which calls the DAO method GenericCatalogDAO.getProducts(), which fires the SQL. The times shown are cumulative times; i.e., the time includes all of the time taken by method calls executed from the reported method. The above data indicates that the SQL has taken 16 milliseconds and the rest of the 31 milliseconds were to process the data and insert it into the JSP page.

Conclusion

This tool demonstrates that using AOP techniques, we can very easily instrument J2EE applications to identify performance problems. The following are some of advantages of this approach towards performance analysis:

Resources

Ramchandar Krishnamurthy is a senior technical architect in the Software Engineering and Technology Labs of Infosys Technologies Limited.


Return to ONJava.com.

Copyright © 2009 O'Reilly Media, Inc.