Tapestry Magic #7: Tapestry Integration With Perf4J

Perf4j is a set of utilities for calculating and displaying performance statistics for Java code and has already been integrated with AOP’s like AspectJ. So I thought why not with our own Tapestry5. Won’t it be nice if we are able to annotate an event handler or a service method with @Profiled and Perf4J will log the details of its duration. That is exactly what we are going to do.

Perf4J can be used for calculations of any method execution in the following way

StopWatch watch = LoggingStopWatch("my_method");
execute_some_method();
watch.stop();

This will log the details as

INFO: start[1230448905165] time[704] tag[my_method]

Using Advices support of Tapestry5, we would do some magic which will do it automatically for any service method or component event handler annotated with @Profiled. This annotation has a number of fields. There is a tag field, which can be used to tag the log for a particular method. There is a message field, which can be used to indicate the status of invocation. There is a level field to specify the logging level.

StopWatch has different implementations for different logging libraries. We start by creating a service which will be responsible for creating a stop watch. Different implementations of this service can be used based on logging library preferences.


public interface StopWatchSource {
   StopWatch create(Profiled profiled);
}

We create an implementation for Log4J library.

public class Log4JStopWatchSource implements StopWatchSource {
   
   public Log4JStopWatchSource(){
   }

   public StopWatch create(Profiled profiled) {
      Level logLevel = Level.toLevel(profiled.level()); 
      Log4JStopWatch stopWatch = new Log4JStopWatch();
      stopWatch.setNormalAndSlowSuffixesEnabled(profiled.normalAndSlowSuffixesEnabled());
      stopWatch.setTag(profiled.tag());
      stopWatch.setTimeThreshold(profiled.timeThreshold());
      stopWatch.setNormalPriority(logLevel);
      stopWatch.setExceptionPriority(logLevel);
      return stopWatch;
   }
}

In the create method we use the information from the annotation and create a logger. Next, we create an advisor interface which will be responsible for advising both component events as well as service methods.The advise method is responsible for advising the service methods which are annotated with @Profiled annotation. The invoke method executes the invocation surrounded by the stop watch.


// Interface
public interface Perf4JServiceAdvisor
{
   void advise(MethodAdviceReceiver receiver);
   void invoke(Invocation invocation, Profiled annotation,
         String className);
}

// Implementation
public class Perf4JServiceAdvisorImpl implements Perf4JServiceAdvisor {

   private StopWatchSource stopWatchSource;

   public Perf4JServiceAdvisorImpl(StopWatchSource stopWatchSource) {
      this.stopWatchSource = stopWatchSource;
   }

   public void advise(final MethodAdviceReceiver receiver) {
      for (final Method method : receiver.getInterface().getMethods()) {
         final Profiled annotation = method.getAnnotation(Profiled.class);
         if (annotation != null) {
            receiver.adviseMethod(method, new MethodAdvice() {

               public void advise(Invocation invocation) {
                  invoke(invocation, annotation, receiver.getInterface().getName());
               }
            });

         }
      }
   }

   public void invoke(Invocation invocation, Profiled annotation,
         String className) {
      final StopWatch watch = stopWatchSource.create(annotation);
      String tag;
      if (Profiled.DEFAULT_TAG_NAME.equals(annotation.tag())) {
         tag = className + "." + invocation.getMethodName();
      } else {
         tag = annotation.tag();
      }
      invocation.proceed();
      watch.stop(tag, annotation.message());
   }

}

In the advise method, we loop over all the methods present in the service interface and add an advice to the methods annotated with @Profiled annotation. In the invoke method we create a stop watch. If the tag is not set in the annotation, we create our own using class name and method name. We allow the method to proceed and then stop the watch.

This advise can be applied to any method using the @Match annotation in the Module class.

   public static void bind(ServiceBinder binder){
      binder.bind(StopWatchSource.class, Log4JStopWatchSource.class);
      binder.bind(Perf4JServiceAdvisor.class, Perf4JServiceAdvisorImpl.class);
   }

   @Match("TapestryTestService")
   public void advisePerf4J(Perf4JServiceAdvisor advisor, MethodAdviceReceiver receiver){
      advisor.advise(receiver);
   }

We can extend our advice to the Component event handlers(or other methods in it) by implementing ComponentClassTransformWorker.

public class Perf4JWorker implements ComponentClassTransformWorker {
   private Perf4JServiceAdvisor advisor;

   public Perf4JWorker(Perf4JServiceAdvisor advisor){
      this.advisor = advisor;
   }

   public void transform(final ClassTransformation transform,
         MutableComponentModel model) {
      for (final TransformMethod method : transform
            .matchMethodsWithAnnotation(Profiled.class)) {
         final Profiled annotation = method.getAnnotation(Profiled.class);
         
         method.addAdvice(new ComponentMethodAdvice() {
            public void advise(ComponentMethodInvocation invocation) {
               advisor.invoke(invocation, annotation, transform.getClassName());
            }
         });
      }
   }

}

In the transform method, we loop over the methods annotated with @Profiled and advise these methods. On invocation of advise we call advisor’s invoke method. Finally we contribute this Worker in the Module class.

   
   public void contributeComponentClassTransformWorker(
         OrderedConfiguration<ComponentClassTransformWorker> configuration, 
         Perf4JServiceAdvisor advisor){
      configuration.add("perf4J", new Perf4JWorker(advisor)); 
   }

One simplification that I have done is not parsing tags and messages.We can allow expressions for method parameters in tags and messages e.g. $0.name meaning call first parameter’s getName() method. This can easily be done by using regular expressions and PropertyAccess service.

Upgrading to Tapestry 5.3

The Advisor can now be more generic as both the service advices and Component method advices are of type MethodAdvice.The rest is very similar.

// Interface
public interface Perf4JServiceAdvisor
{
   void advise(MethodAdviceReceiver receiver);

   MethodAdvice getAdvice(Profiled annotation, String className);
}

// Implementation
public class Perf4JServiceAdvisorImpl implements Perf4JServiceAdvisor {

   private StopWatchSource stopWatchSource;

   public Perf4JServiceAdvisorImpl(StopWatchSource stopWatchSource) {
      this.stopWatchSource = stopWatchSource;
   }

   public void advise(final MethodAdviceReceiver receiver) {      
      for (final Method method : receiver.getInterface().getMethods())
      {
         final Profiled annotation = method.getAnnotation(Profiled.class);
         if (annotation != null) {
            receiver.adviseMethod(method, getAdvice(annotation, 
               receiver.getInterface().getName()));
         }
      }
   }

   public MethodAdvice getAdvice(final Profiled annotation, final String className){
      return  new MethodAdvice() {
         public void advise(MethodInvocation invocation) {
            invoke(invocation, annotation, className);
         }
      };
   }
   
   private void invoke(MethodInvocation invocation, Profiled annotation,
         String className) {
      final StopWatch watch = stopWatchSource.create(annotation);
      invocation.proceed();
      String tag;
      if (Profiled.DEFAULT_TAG_NAME.equals(annotation.tag())) {
         tag = className + "." + invocation.getMethod().getName();
      } else {
         tag = annotation.tag();
      }
      watch.stop(tag, annotation.message());
   }

}

Also the ComponentClassTransformWorker has been deprecated in favour of ComponentClassTransformWorker2. The implementation is very similar (Checkout the plastic related posts to learn more)

public class Perf4JWorker implements ComponentClassTransformWorker2
{
   private Perf4JServiceAdvisor advisor;

   public Perf4JWorker(Perf4JServiceAdvisor advisor)
   {
      this.advisor = advisor;
   }

   public void transform(final PlasticClass plasticClass, 
     TransformationSupport support, MutableComponentModel model)
   {
      for(final PlasticMethod method : plasticClass.getMethodsWithAnnotation(Profiled.class))
      {
         method.addAdvice(advisor.getAdvice(method.getAnnotation(Profiled.class),
           plasticClass.getClassName()));
      }
   }

}

Finally remember to contribute Perf4JWorker to ComponentClassTransformWorker2 in the Module class

   @Contribute(ComponentClassTransformWorker2.class)
   public void contributeComponentClassTransformWorker2(
         OrderedConfiguration<ComponentClassTransformWorker2> configuration, 
         Perf4JServiceAdvisor advisor){
      configuration.add("perf4J", new Perf4JWorker(advisor)); 
   }

The source for Tapestry 5.3-alpha-2 is here

About these ads

Tagged: , ,

3 thoughts on “Tapestry Magic #7: Tapestry Integration With Perf4J

  1. Borut September 1, 2011 at 6:50 PM Reply

    Very aducational post!

    I do have one question. I want to profile some private methods in the class which implements some interface. It doesn’t look nice if I declare those methods which I want to profile in the interface. Is there a way in T5.3-beta-1 to use @Match or something else to achive my goal?

    Thanks!

    • tawus September 5, 2011 at 3:54 PM Reply

      Thanks Borut

      As private methods are internal to the class, it doesn’t make much sense to apply advises to them and so most AOPs don’t support it. You can always use the direct Perl4j implementation in that case. You can also use Plastic directly in your use-case.

      • Borut September 5, 2011 at 6:25 PM

        You’re welcome.

        You probably meant “…it doesn’t make much sense to apply…”?

        I did it now without the @Profiled, at least on some methods, and it works, although the code is “polluted” in some way which I was trying to avoid.

        Now I tried to customize the way tag or message gets logged by using EL expressions as parameters to @Profiled and it seems it doesn’t work. I am looking at your tests and see you didn’t use something like

        @Profiled(tag = “SEARCH {$0}”)
        Results search(String q);

        The {$0} is not expanded and gets written out as it is. What could be the case? I have included

        org.apache.commons
        commons-jexl
        2.0

        Thanks for any hints!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 91 other followers

%d bloggers like this: