Functional requirements for mission critical applications often include software service level agreements (SLAs), which specify the maximum allowable latency for specific operations. Such requirements necessitate the monitoring of application performance, either at system testing stage or post deployment. This article will demonstrate how real-time performance tracing/monitoring can be achieved for spring applications using the functionality provided in Spring AOP and the Apache Log4j toolkit. Introduction Assume that as a solution developer/designer, you are given a list of semi-feasible functional requirements which a proposed application has to meet. Whilst reading through the list you parrot the seemingly non-controversial contents back to yourself. That is of course until you reach a line that reads something along the lines of “requests of type ‘y’ have to complete in ‘x’ seconds at the most”. Given that a typical application will have several points of failure which are not within your control as a solution designer, you will be forgiven for going back to your user base and explaining that such a requirement is quite simply not feasible. If you are really unlucky, you may have to go home and start working on yet another revision of your curriculum vitae. But since most users are actually reasonable people, you will probably achieve a compromise along the lines of “if requests of type ‘y’ are taking longer than ‘x’, then perform this action”. Suffice it to say that the action to be performed falls under the general heading “details”; but you would have at least reduced your requirement to something a bit more tractable. This type of functional requirement is no longer uncommon and is often referred to, interchangeably either as a Latency Requirement or Software Service Level Agreement (SLA for short). SLAs generally take the form “operations of type ‘y’ must complete within ‘x’ units of time”. As an example, the backend for an online stock trading platform might include a restriction of the form “all trades must be submitted to the exchange within 5 seconds of being placed”. The challenges that performance SLAs present to software developers are two-fold. At the design and implementation phase, the emphasis is on ensuring that the application is built in such a way as to encourage fast enough throughput in order to bring the average-case latency in line with the SLA. The second challenge concerns the monitoring of the application’s performance in real-time, either at system testing stage or post deployment, so as to detect/predict possible breaches of its SLA. In this tutorial, we will focus on how to leverage the functionality of the Spring Framework to achieve real-time performance measurement and monitoring. This is a hands-on tutorial, so please download the companion source archive and load the files into your preferred IDE. The source files which comprise the archive are shown in Figure 1. Note that, in addition to the Spring binaries, the lib folder of the companion archive also contains the binaries for the following open-source dependencies: Apache Log4J JAMon Although not strictly necessary, it is advisable to download Apache’s Chainsaw application, which can be used for viewing the logs of remote applications. For the benefit of the uninitiated, we will begin with a very simple primer on Aspect Oriented Programming (AOP); this will cover the basics needed to follow the examples in this article. For more detailed information, please see the links provided in the resources section. If you are already familiar with AOP, it may well be better to skip the next subsection altogether. A Primer on AOP Object Oriented (OO) programming provides for application entities and behaviour to be encapsulated in a set of classes. Although this is quite effective, and would suffice for most application, the truth is that there is certain behaviour in applications that appear everywhere and yet do not really belong anywhere. Examples abound when you look at non-AOP code in detail: the logging of entry and exit trace messages, operation-level authentication and authorization, and transaction control to name but a few. AOP, or Aspect Oriented Programming to give it its full name, is a means of modularizing and externalizing functionality that spans multiple classes. In AOP terminology such functionality are referred to as cross cutting concerns. If we go back to the example on logging, a logging/error-reporting strategy actually spans multiple classes, and may not really be relevant to the functionality encapsulated by the logged classes. With AOP the log strategy can be externalized as a concern to which classes and methods can be added as and when necessary. The main concepts from AOP which we are interested in for the purposes of this tutorial are: cross cutting concerns; advice; pointcut; and aspect. The first of these has already been described in the preceding paragraphs; the others are described next. Advice: Encapsulates externalized behaviour which can be applied to class instances at configured points during the execution of an application; for example, the logging of an entry or exit trace message can be thought of as advice types. Advice can also be thought of as the physical code which models/implements the logic of a cross cutting concern. Pointcut: A point in the execution of a program at which cross cutting concerns should be applied. This is the point at which the code encapsulated by an advice is executed. Aspect: An aspect is the combination of an advice and one or more pointcut definitions. For more information on AOP, please see the resources section of this article. In the next section we will look at a basic service implementation, whose performance we will monitor via Spring AOP. The Service to Monitor The service to monitor is defined by the contract interface com.myorg.service.MyService, where the operation being monitored are implementations of the epsilon() method. The objective of this tutorial is to show how the start and end time of invocations of this method can be intercepted, so as to provide the duration of such invocations. We will focus on two means of monitoring with Spring AOP, with Spring’s own PerformanceMonitorInterceptor and the JamonPerformanceMonitorInterceptor. The latter, although part of the spring distribution, relies on the JAMon application monitoring library. It is worth stating that the full features of JAMon (specifically the monitoring web-based UI) is only really available to web applications, and not standalone Java apps. Although separate implementations of the service are provided for the Spring and JAMon interceptor examples, this is not a necessity for real world implementations. As you will see, the reason for doing so is merely to ensure clarity of object hierarchies in the tutorial’s Spring configuration file. The first example, covered in the following section, looks at Spring’s PerformanceMonitorInterceptor. Monitoring with Spring’s PerformanceMonitorInterceptor Using Spring’s performance monitor is quite simple and can be done without embedding profiling code directly into application classes. To examine how this is done, we first of all need an implementation of the service interface com.myorg.service.MyService; this is provided by the class com.myorg.service.springmon.MyServiceSpringImpl which is shown in Listing 1. Listing 1: MyServiceSpringImpl package com.myorg.service.springmon; import com.myorg.service.MyService; public class MyServiceSpringImpl implements MyService { protected static final long DEFAULT_SLEEP_INTERVAL = 100; private long sleepInterval; public MyServiceSpringImpl() { setSleepInterval(DEFAULT_SLEEP_INTERVAL); } public void epsilon() { try{ Thread.sleep(getSleepInterval()); }catch (InterruptedException int_exce){ throw new RuntimeException("Service interrpted. Exiting.", int_exce); } } public long getSleepInterval() {return sleepInterval;} public void setSleepInterval(long sleepInterval) {this.sleepInterval = sleepInterval;} } The implementation of the contract method epsilon() simply causes the thread to sleep for a preset interval. Consequently, we should expect the performance monitor to register a value reasonably close to the sleep interval. To make use of this service, we have to declare it in the application’s Spring configuration file. Not only that, but we also have to indicate that the epsilon() method is a pointcut at which we want monitoring advice executed in any thread of execution cutting across it. The snippet of the configuration to which this relates is shown in Listing 2, which is an excerpt of the application configuration file beans-context.xml. Listing 2: beans-context.xml <?xml version="1.0" encoding="UTF-8"?> <beans xmlns="<a href="https://www.springframework.org/schema/beans">https://www.springframework.org/schema/beans</a>" xmlns:xsi="<a href="https://www.w3.org/2001/XMLSchema-instance">https://www.w3.org/2001/XMLSchema-instance</a>" xmlns:aop="<a href="https://www.springframework.org/schema/aop">https://www.springframework.org/schema/aop</a>" xsi:schemaLocation="<a href="https://www.springframework.org/schema/beans">https://www.springframework.org/schema/beans</a> <a href="https://www.springframework.org/schema/beans/spring-beans-2.0.xsd">https://www.springframework.org/schema/beans/spring-beans-2.0.xsd</a> <a href="https://www.springframework.org/schema/aop">https://www.springframework.org/schema/aop</a> <a href="https://www.springframework.org/schema/aop/spring-aop-2.0.xsd">https://www.springframework.org/schema/aop/spring-aop-2.0.xsd</a>"> <bean id="springMonitoredService" class="com.myorg.service.springmon.MyServiceSpringImpl"/> <bean id="springMonitoringAspectInterceptor" class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor"> <property name="loggerName" value="com.myorg.SPRING_MONITOR"/> </bean> <aop:config> <aop:pointcut id="springMonitoringPointcut" expression="execution(* com.myorg.service..MyServiceSpringImpl.epsilon(..))"/> <aop:advisor pointcut-ref="springMonitoringPointcut" advice-ref="springMonitoringAspectInterceptor"/> </aop:config> </beans> The configuration file opens with a definition of the service bean, with id springMonitoredService, and then a declaration of the performance monitor springMonitoringAspectInterceptor. The latter of these serves as the advice which we want applied at the invocation of the service’s epsilon() method. Having defined the service, and a representation of the advice, we specify the pointcut at which we want the advice applied. This is done within the <aop:config> element of the bean definition file. This contains a pointcut with id springMonitoringPointcut, which specifies a regular expression that matches all invocations of the epsilon() method in objects of type com.myorg.service..MyServiceSpringImpl. Observe the use of the double period (..) notation in the specification of the class name. This is akin to the pattern com.myorg.service.*.MyServiceSpringImpl. Observe also that the pointcut is actually a bean in itself. Finally, all we need to complete this example is a definition of the aspect; which, if you recall, is a combination of the pointcut and the advice. This is contained in the element <aop:advisor>, which references both the pointcut and the advice to form an aspect. Before we move onto the client application, please note that a log4j properties file is included in the config folder of the companion archive. This specifies appenders and layouts that will process the log statements generated by the sample application. At this point you may be wondering where such log messages will come from since we have not actually performed any logging thus far. The answer lies in the logic of the Spring performance monitor, which actually prints task durations via log4j using a TRACE level message. Observe that the log4j file provided declares a SocketHubAppender, which will allow viewing of log messages with Apache’s chainsaw. The use of chainsaw is not strictly necessary for this example, but is provided simply as a means of demonstrating how a complete solution can be setup in the real world. This is more relevant for the JAMon example as we do not have recourse to the JAMon GUI–it is only really applicable to web applications. All that is left to do is to provide a client for invoking the service. A single client application is used for this tutorial; however, a different method is provided for invoking each example. As such, some light and judicious use of Java’s commenting construct will be required to exclude the examples that you do not want to run. Listing 3 shows the main contents of the example client com.myorg.MyClientApp. Listing 3: MyClientApp package com.myorg; import org.springframework.context.ApplicationContext; import org.springframework.context.support.ClassPathXmlApplicationContext; import com.myorg.service.MyService; public class MyClientApp { private static final int SIMULATED_INVOCATION_COUNT = 100; private static void executeExampleWithEmbeddedSpringMonitoring( ApplicationContext context) { MyService service = (MyService)context.getBean( "serviceWithEmbeddedSpringProfilling"); for (int i=0;i<SIMULATED_INVOCATION_COUNT;i++) service.epsilon(); } private static void executeSpringMonitoringExample( ApplicationContext context) { MyService service = (MyService)context.getBean( "springMonitoredService"); for (int i=0;i<SIMULATED_INVOCATION_COUNT;i++) service.epsilon(); } private static void executeJamonMonitoringExample( ApplicationContext context) { MyService service = (MyService)context.getBean( "jamonMonitoredService"); for (int i=0;i<SIMULATED_INVOCATION_COUNT;i++) service.epsilon(); } public static void main(String[] args) { ApplicationContext context = new ClassPathXmlApplicationContext("beans-context.xml"); executeExampleWithEmbeddedSpringMonitoring(context); executeSpringMonitoringExample(context); executeJamonMonitoringExample(context); while (true){ //do nothing and just //keep the application alive //long enough for us to admire output } } } The main method simply loads the application context, and calls the three methods which respectively invoke the service implementations corresponding to the examples provided in this tutorial. In this case, we are only concerned with the invocation executeSpringMonitoringExample(context);, and as such we can comment out the other invocations at this stage. Executing the example client results in output not too dissimilar to the following. RACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 94 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 110 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 93 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 110 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 93 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 110 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 94 When viewed via chainsaw (i.e. by setting up a SocketHubReceiver on the port specified in log4j.properties), the output is of the form shown in Figure 2. If you examine the output closely, you will note references to StopWatch; this, in fact, is the name of the Spring class that performs the actual task of timekeeping. To see how the class works, we will try to replicate the functionality in the last example without the benefit of AOP. In other words, we will actually embed the profiling logic directly in our service implementation. Apart from providing a more in depth view of how the monitoring code works underneath, the extra coding required should hopefully dissuade most people from doing this. And, as such, drive home the logic behind using AOP in place of anything else! The class com.myorg.service.springmon.MyServiceWithEmbeddedSpringProfilling, which is shown in listing 4, is a different implementation of the service that invokes the performance monitoring functionality explicitly within the epsilon() method. It is easy to observe from inspection of the source code that performance monitoring is accomplished by simply instantiating a new instance of the class org.springframework.util.StopWatch. Listing 4: MyServiceWithEmbeddedSpringProfilling package com.myorg.service.springmon; import org.springframework.util.StopWatch; public class MyServiceWithEmbeddedSpringProfilling extends MyServiceSpringImpl { public void epsilon() { StopWatch monitor = new StopWatch(); monitor.start("epsilon"); super.epsilon(); monitor.stop(); } } Like its physical namesake, the stopwatch simply records the time between the invocation of its start(...) and stop() methods. Information about the tasks performed between starting and stopping the monitor can be obtained by calling the getTaskInfo() method. To execute this example, simply comment out all other invocations in the main method of the test client MyClientApp with the exception of executeExampleWithEmbeddedSpringMonitoring(context);. Doing so will execute the code for the above example in isolation of the other two, and should produce output similar to the following excerpt. TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 110 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 93 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 110 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 94 TRACE main - StopWatch 'com.myorg.service.MyService.epsilon': running time (millis) = 109 You will note that the above output is quite similar to the output from the first example. In essence, we have achieved not very much extra (in terms of functionality) by embedding the monitoring code directly in our application; other than of course cluttering the solution needlessly. In the next section we will look at monitoring with the JAMon library. Monitoring with Spring’s JamonPerformanceMonitorInterceptor JAMon consists of a library for performing latency monitoring as well as a web GUI which can be used in web applications to view the output from the monitoring library. Given that a number of applications do not run in a web container, the GUI is not a feasible option for many solutions. However, its base package offers functionality quite similar to that which is native in spring. Also, the spring distribution includes a performance monitor interceptor (JamonPerformanceMonitorInterceptor) which serves as a bridge to the JAMon toolkit. This can be combined with Apache’s Chainsaw to replicate functionality that is not too dissimilar (for practical purposes) to that of the JAMon GUI. Although not necessary in any other context, we will use a separate implementation of the service to illustrate monitoring with the JAMon interceptor. This implementation is shown in listing 5, and is only provided for the clarity of the Spring AOP configuration. As such, you will note that it is identical to the implementation of the service shown in the first example. Listing 5: MyServiceJamonImpl package com.myorg.service.jamon; import com.myorg.service.MyService; public class MyServiceJamonImpl implements MyService { protected static final long DEFAULT_SLEEP_INTERVAL = 100; private long sleepInterval; public MyServiceJamonImpl() {setSleepInterval(DEFAULT_SLEEP_INTERVAL);} public void epsilon() { try{ Thread.sleep(getSleepInterval()); }catch (InterruptedException int_exce){ throw new RuntimeException("Service interrpted. Exiting.", int_exce); } } public long getSleepInterval() {return sleepInterval;} public void setSleepInterval(long sleepInterval) {this.sleepInterval = sleepInterval;} } The definition of the service and the spring aspect are shown in the following excerpt from the spring configuration file beans-context.xml. Note that the only material difference between this and the first example is that the advice bean is an instance of the class org.springframework.aop.interceptor.JamonPerformanceMonitorInterceptor. Listing 6: beans-context.xml <?xml version="1.0" encoding="UTF-8"?> <beans .............> <bean id="jamonMonitoredService" class="com.myorg.service.jamon.MyServiceJamonImpl"/> <bean id="jamonMonitoringAspectInterceptor" class="org.springframework.aop.interceptor.JamonPerformanceMonitorInterceptor"> <property name="loggerName" value="com.myorg.JAMON_MONITOR"/> </bean> <aop:config> <aop:pointcut id="jamonMonitoringPointcut" expression= "execution(* com.myorg.service..MyServiceJamonImpl.epsilon(..))"/> <aop:advisor pointcut-ref="jamonMonitoringPointcut" advice-ref="jamonMonitoringAspectInterceptor"/> </aop:config> </beans> To execute this example in isolation of the other two, comment out all invocations in the main method of the test client MyClientApp.java with the exception of the line executeJamonMonitoringExample(context);. The output generated by doing so should be similar to the following listing. TRACE main - JAMon performance statistics for method [com.myorg.service.MyService.epsilon]: JAMon Label=com.myorg.service.MyService.epsilon, Units=ms.: (LastValue=94.0, Hits=1.0, Avg=94.0, Total=94.0, Min=94.0, Max=94.0, Active=0.0, Avg Active=1.0, Max Active=1.0, First Access=Sun May 03 20:05:11 BST 2009, Last Access=Sun May 03 20:05:11 BST 2009) TRACE main - JAMon performance statistics for method [com.myorg.service.MyService.epsilon]: JAMon Label=com.myorg.service.MyService.epsilon, Units=ms.: (LastValue=93.0, Hits=2.0, Avg=93.5, Total=187.0, Min=93.0, Max=94.0, Active=0.0, Avg Active=1.0, Max Active=1.0, First Access=Sun May 03 20:05:11 BST 2009, Last Access=Sun May 03 20:05:12 BST 2009) TRACE main - JAMon performance statistics for method [com.myorg.service.MyService.epsilon]: JAMon Label=com.myorg.service.MyService.epsilon, Units=ms.: (LastValue=110.0, Hits=3.0, Avg=99.0, Total=297.0, Min=93.0, Max=110.0, Active=0.0, Avg Active=1.0, Max Active=1.0, First Access=Sun May 03 20:05:11 BST 2009, Last Access=Sun May 03 20:05:12 BST 2009) ........................ Figure 3 illustrates the output of this example as seen through the Chainsaw GUI. Note that this example actually utilises the JAMon binaries which are included in the lib folder of the companion archive. An interesting exercise for the reader to perform is to export the service implementation as a web service, package and deploy the application to a web container taking care to also configure the JAMon GUI in the web application descriptor. In the next section, we will examine some alternative techniques for performance monitoring, which do not fall within the remit of this tutorial. Other Solutions for Performance Monitoring To be clear, the technique described in this tutorial is reliant on AOP and may be difficult to apply to legacy applicationsespecially if the applications are not built with the spring framework. That said performance analysis of legacy/existing applications can also be accomplished with a number of commercial tools (e.g. JProfiler) which allow developers to identify potential bottlenecks in existing code. There are also more intrusive commercial third-party infrastructure components, such as JVMs, which offer facilities for real-time performance monitoring. Amongst the products in this space is RTPM from Azul systems. Choosing one of these tools obviously involves making implementation/deployment choices which may take solution developers down a route which is less travelled by those in their respective organizations. Having said that, there are some real drawbacks to the Spring AOP approach. The most important of which is that there is no facility for asynchronous notification. If monitoring is enabled in the deployment environment, then it would be nice to have some means of issuing notifications when the application performance has degraded beyond a pre-set watermark. If your monitoring requirements are complex in nature, than you may well be better off investigating a dedicated and commercial solution to the problem. Summary The emphasis of this tutorial was on how to augment spring applications, in a non intrusive manner, so as to obtain real-time performance metrics which can either be used to provide feedback to an iterative design process, or to monitor the behaviour/performance of applications in their deployment environment/home habitat. The tutorial has provided a number of examples which demonstrate how to use classes native to the Spring application framework to achieve real-time performance reporting and monitoring. It has provided an example to show how Spring AOP can be combined with the JAMon application monitoring tool. Software Development