Performance Analysis of J2EE Applications Using AOP Techniques

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:

• Uses a ThreadLocal variable to hold the request ID and the sequence of method execution.
• Opens a socket writer to the Instrumentation Server.
• Provides helper methods to construct a colon (:) -separated string to be transmitted to the Instrumentation Server.
• Provides helper methods to write to the socket.

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.

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:

• The instrumentation is non-intrusive and can be applied to the application during the deployment without any modifications to the code. The instrumentation can be very easily turned on or off.

• By inserting probes only into suspect methods, we can minimize the overhead of performance analysis. With targeted instrumentation, the application can be profiled even in load-testing environments.

• By utilizing open source AOP frameworks like Aspectwerkz, a cheap in-house alternative for expensive performance analysis tools can be very quickly developed.

Resources

• Source code for this article

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

Return to ONJava.com.