This article will address a great mystery to most of us, how long do those EL calls really take? The most straight forward approach to solving that question is using Aspect Oriented Programming. With just a couple of simple pointcuts we can intercept calls to org.jboss.el.ValueExpressionImpl.getValue(..) and org.jboss.el.MethodExpressionImpl.invoke(..). After that, just wrap those methods in System.currentTimeMillis() and log it.

So lets get started. The versions I used to test with are EAP 4.3_CP02 for those non enterprise customers any 4.2.x version should work. The JDK version used is 1.5_15 and the Seam version 2.0.3.CR1 although that is inconsequential.

Step 1

The first step is to enable Load Time Weaving for JBossAOP.

• Open to JBOSS_HOME/server/<configuration>/deploy/jboss-aop-jdk50.deployer/META-INF/jboss-service.xml and set EnableLoadtimeWeaving to true.
• Assuming you are using JDK5/6 copy JBOSS_HOME/server/<configuration>/deploy/jboss-aop-jdk50.deployer/pluggable-instrumentor.jar to JBOSS_HOME/bin/
• Open JBOSS_HOME/bin/run.conf and add:

JAVA_OPTS="$JAVA_OPTS -javaagent:pluggable-instrumentor.jar"

Step 2

Now, before we get to the main part, lets go ahead and setup the jboss-log4j.xml to correctly handle the Interceptors.

Open up JBOSS_HOME/server/<configuration>/conf/jboss-log4j.xml and add:

<appender name="EL_METRICS" class="org.jboss.logging.appender.DailyRollingFileAppender">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="File" value="${jboss.server.log.dir}/el_metrics.log"/>
      <param name="Append" value="false"/>

      <!-- Rollover at midnight each day -->
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>

      <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%m%n"/>
      </layout>
   </appender>

and

<category name="org.jboss.injbossaop.ValueExpressionMetrics">
      <priority value="INFO"/>
      <appender-ref ref="EL_METRICS"/>
   </category>
   <category name="org.jboss.injbossaop.MethodExpressionMetrics">
      <priority value="INFO"/>
      <appender-ref ref="EL_METRICS"/>
   </category>

As you can see all of the log statements in the interceptors will be sent to JBOSS_HOME/server/<configuration>/log/el_metrics.log

Step 3

It's time to deploy the .aop file to the server. Download elaopmetrics.aop which was uploaded to this directory and put that into JBOSS_HOME/server/<configuration>/deploy. The elaopmetrics.aop file is one of the ways to package and deploy JBossAOP code to the server. The structure contains the java classes and a META-INF/jboss-aop.xml that defines the pointcuts and such.

Step 4

Start JBoss and deploy a Seam WAR or EAR file and access a page. Go to your filesystem and find JBOSS_HOME/server/<configuration>/log/el_metrics.log In my example I seam-gen'd a new Entity called Car and accessed car.seam. The resulting output was:

[ExpressionMetrics] 0ms ValueExpression: #{traceData}
[ExpressionMetrics] 0ms ValueExpression: #{traceData}
[ExpressionMetrics] 1ms ValueExpression: #{traceData}
[ExpressionMetrics] 0ms ValueExpression: DynamicCRUD
[ExpressionMetrics] 0ms ValueExpression: #{projectName}:
[ExpressionMetrics] 0ms ValueExpression: #{identity.loggedIn}
[ExpressionMetrics] 1ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 1ms ValueExpression: #{identity.loggedIn}
[ExpressionMetrics] 0ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 0ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 1ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 0ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 1ms ValueExpression: #{not identity.loggedIn}
[ExpressionMetrics] 0ms ValueExpression: #{conversation.longRunning}
[ExpressionMetrics] 1ms ValueExpression: #{conversation.id}
[ExpressionMetrics] 1ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{invalid}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: name #{invalid?'errors':''}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{required}
[ExpressionMetrics] 0ms ValueExpression: #{invalid?'errors':''}
[ExpressionMetrics] 0ms ValueExpression: #{SeamExampleProjectEntityManagerFactory}
[ExpressionMetrics] 10ms ValueExpression: #{carHome.instance.name}
[ExpressionMetrics] 0ms ValueExpression: #{invalid}
[ExpressionMetrics] 6ms ValueExpression: #{!carHome.managed}
[ExpressionMetrics] 4ms ValueExpression: #{!carHome.managed}
[ExpressionMetrics] 5ms ValueExpression: #{!carHome.managed}
[ExpressionMetrics] 5ms ValueExpression: #{!carHome.managed}
[ExpressionMetrics] 4ms ValueExpression: #{!carHome.managed}
[ExpressionMetrics] 4ms ValueExpression: #{carHome.managed}
[ExpressionMetrics] 4ms ValueExpression: #{carHome.managed}
[ExpressionMetrics] 0ms ValueExpression: #{traceData}

The Code

For those interested in how this all works, here is the necessary code:

MethodExpressionMetrics.java:

public class MethodExpressionMetrics implements Interceptor {

	private static Logger log = Logger.getLogger(MethodExpressionMetrics.class);
	
	public String getName() {
		return "MethodExpressionMetrics";
	}

	public Object invoke(Invocation invocation) throws Throwable {
		
		long startTime = System.currentTimeMillis();
		try {
			return invocation.invokeNext();
		} finally {
			long elapsedTime = System.currentTimeMillis() - startTime;
			java.lang.reflect.Method m = ((MethodInvocation) invocation).getMethod();
			Field field = invocation.getTargetObject().getClass().getDeclaredField("expr");
			field.setAccessible(true);
			String expr = (String)field.get(invocation.getTargetObject());
			log.info("[ExpressionMetrics] " + elapsedTime + "ms MethodExpression: " + expr);
		}

	}

}

ValueExpressionMetrics.java:

public class ValueExpressionMetrics implements Interceptor {

	private static Logger log = Logger.getLogger(ValueExpressionMetrics.class);
	
	public String getName() {
		return "ValueExpressionMetrics";
	}

	public Object invoke(Invocation invocation) throws Throwable {

		long startTime = System.currentTimeMillis();
		try {
			return invocation.invokeNext();
		} finally {
			long elapsedTime = System.currentTimeMillis() - startTime;
			java.lang.reflect.Method m = ((MethodInvocation) invocation).getMethod();
			Field field = invocation.getTargetObject().getClass().getDeclaredField("expr");
			field.setAccessible(true);
			String expr = (String) field.get(invocation.getTargetObject());
			log.info("[ExpressionMetrics] " + elapsedTime + "ms ValueExpression: " + expr);
		}

	}

}

jboss-aop.xml:

<aop>
   <bind pointcut="execution(public java.lang.Object org.jboss.el.ValueExpressionImpl->getValue(..))">
       <interceptor class="org.jboss.injbossaop.ValueExpressionMetrics"/>
   </bind>

   <bind pointcut="execution(public java.lang.Object org.jboss.el.MethodExpressionImpl->invoke(..))">
       <interceptor class="org.jboss.injbossaop.MethodExpressionMetrics"/>
   </bind>
</aop>

What next?

I have plenty of ideas on how to evolve this basic implementation to something more user friends, but for now, those who are command-line friendly will be happy.