Application logic can be broken into 2 distinct areas, core business logic and cross cutting concerns. Business logic is code written to satisfy a functional requirement, while a cross cutting concern is 'utility' logic that is agnostic to any specific business process and required by many parts of the application. Examples include logging, transaction management, performance monitoring and security. While none of these address a functional requirement, they remain fundamental parts of the application runtime.
Cross cutting concerns present 2 main challenges.
- They tend to be 'scattered' across the application which can lead to considerable duplicate code. Logging or performance monitoring is a good example.
- They become tangled with application business logic and result in code that is difficult to maintain because there is no clear Separation of Concerns.
Key Terms
The detailed inner workings of AOP is well beyond the scope of this post. However, I've provided a brief definition of key terms that are referred to throughout this tutorial.
Aspect - A self contained module that attempts to address a specific cross cutting concern. In this tutorial the Aspect will contain performance monitoring functionality.
Advice - Logic that is invoked at a specific point in a programs execution.
Join Point - A specific point in a programs execution where advice is applied. Note that advice can be applied before and after a Join Point.
Pointcut - An expression that identifies Join Points matching certain criteria. For example we can define a Pointcut that identifies all public methods in a package. These specific points in program execution (JoinPoints) have advice applied to them at runtime.
How does it work?
If Advice (performance monitoring logic in this case) is completely separate from the business logic, how is it actually called? AOP takes care of this at runtime by wrapping the target object inside a proxy. The proxy intercepts incoming requests to the target object and calls the performance monitor 'utility' logic before it calls the target object. The proxy can also invoke utility logic after the target object has been called. Figure 1.0 below shows the steps involved.
 |
| Figure 1.0 - AOP Proxy |
This sample code described in this tutorial will demonstrate some of Springs AOP capabilities by showing you how to build a simple performance monitor. Springs AOP support can be set up with either XML configuration or annotations. The XML approach is typically used in older applications running Spring 2.5, whereas newer applications running Spring 3.X typically use annotations. For completeness this tutorial will cover both approaches.
Project Structure
I've create 2 separate projects, one using XML configuration and one using annotations. The project structure is identical for both - the only difference is the configuration. To keep things simple both applications will be kicked off via a main method and call a simple Service. We'll then use AOP to apply performance monitoring to the service call. The structure of both projects is shown below.
 |
| Figure 2.0 - Project Structure |
I'll start off by explaining the components that are identical in both the XML and annotation driven approaches. Then I'll move on to explaining the configuration specific to each approach. Full source code for both projects will be available to download at the bottom of this post.
Service Interface
CalculationService.java is an interface that defines the simple service method shown below. Note that programming to interfaces is regarded as good practice, but has even more significance when using Springs AOP support. In order for Spring to use the dynamic proxy approach described earlier (see figure 1.0), it is expected that the target object (CalculationServiceImpl in this case) implements an interface. Its also possible to use AOP on a class that doesn't implement an interface. In this case CGLIB is used to proxy the target object.
1: package com.blog.samples.aop;
2:
3: /**
4: * Dummy service interface
5: *
6: */
7: public interface CalculationService
8: {
9: /**
10: * A dummy method
11: *
12: * @param employee_p
13: * @return
14: */
15: public void dummyServiceMethod();
16: }
Service Implementation
CalculationServiceImpl.java implements the service interface defined above. The dummyServiceMethod simply logs a message and calls the randomSleep method to sleep the current thread for a random period of time. This allows us to simulate varying response times from the service method which will useful for testing our performance monitor later.
1: package com.blog.samples.aop;
2:
3: import org.apache.log4j.Logger;
4:
5: /**
6: * Dummy service calculates implementation implements dummyServiceMethod.
7: *
8: */
9: public class CalculationServiceImpl implements CalculationService
10: {
11: private static final Logger logger_c = Logger.getLogger(CalculationServiceImpl.class);
12:
13: /**
14: * dummyServiceMethod simply logs a message and calls randomSleep to
15: * sleep the current thread for a random period of time. This allows us
16: * to simulate varying response times from the service method which is
17: * useful for testing our performance monitor
18: *
19: * @param employee_p
20: * @return
21: */
22: public void dummyServiceMethod()
23: {
24: logger_c.debug("Doing some service stuff here...");
25:
26: /* Sleep thread for random period so as to vary service execution time */
27: randomSleep();
28: }
29:
30: /**
31: * Sleep thread for random period
32: */
33: private void randomSleep()
34: {
35: try
36: {
37: Thread.sleep((long)(Math.random() * 1000));
38: }
39: catch (InterruptedException ie_p)
40: {
41: logger_c.error("Error occurred sleeping thread", ie_p);
42: }
43: }
44: }
Test Harness
RunTest.java uses a main method to load the Spring configuration and invokes the test service 50 times. We call the service 50 times as it helps demonstrate some of the statistics that can be gathered by the performance monitor defined later.
1: package com.blog.samples.aop;
2:
3: import org.apache.log4j.Logger;
4: import org.springframework.context.support.ClassPathXmlApplicationContext;
5:
6: public class RunTest
7: {
8: private static final Logger logger_c = Logger.getLogger(RunTest.class);
9:
10: public static void main (String [] args)
11: {
12: logger_c.debug("loading spring application context");
13: ClassPathXmlApplicationContext applicationContext = new ClassPathXmlApplicationContext("classpath:spring-config.xml");
14:
15: /* get been from application context */
16: CalculationService calculationService = (CalculationService)applicationContext.getBean("calculationService");
17:
18: /* call service 50 times so that we can see aggregated performance statistics for service call */
19: for(int i=0; i<50; i++)
20: {
21: /* invoke dummy service */
22: calculationService.dummyServiceMethod();
23: }
24:
25: /* close down spring application context */
26: applicationContext.stop();
27: }
28: }
Line 16 - load calculation service from bean factory
Lines 19 to 23 - invoke calculation service 50 times so that we can gather a variety of metrics using the performance monitor (defined later).
Spring Configuration (XML Approach)
This section will detail the components required to enable AOP using traditional XML configuration. The Calculation Service bean, performance monitor bean and AOP configuration are defined in spring-configuration.xml below.
1: <?xml version="1.0" encoding="UTF-8"?>
2: <beans xmlns="http://www.springframework.org/schema/beans"
3: xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
4: xmlns:context="http://www.springframework.org/schema/context"
5: xmlns:aop="http://www.springframework.org/schema/aop"
6: xsi:schemaLocation="http://www.springframework.org/schema/context
7: http://www.springframework.org/schema/context/spring-context-2.5.xsd
8: http://www.springframework.org/schema/beans
9: http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
10: http://www.springframework.org/schema/aop
11: http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">
12:
13:
14: <!-- Calculation Service bean definition - this is the bean that we want to monitor performance on -->
15: <bean id="calculationService" class="com.blog.samples.aop.CalculationServiceImpl" />
16:
17: <!-- ================================================================== -->
18: <!-- A O P C O N F I G B E A N S -->
19: <!-- ================================================================== -->
20:
21: <!-- Performance Monitor bean definition - this bean contains performance monitoring logic
22: like starting and stopping the monitoring, logging statistics etc -->
23: <bean id="performanceMonitor" class="com.blog.samples.aop.PerformanceMonitor" />
24:
25: <!-- AOP configuration -->
26: <aop:config>
27:
28: <!-- Name of the Aspect we're defining -->
29: <aop:aspect ref="performanceMonitor">
30:
31: <!--
32: the Pointcut expression specifies where the advice (performance monitoring code) will
33: be applied. Pointcut expressions are very flexible and can be as specific or as generic
34: as you like. In this instance we configured the Pointcut expression so that it covers
35: all methods in the com.blog.samples.aop.CalculationService class. However, we could
36: have configured it so that advice is only applied to a single Service method, or even
37: opened it up to all classes within the com.blog.samples.aop package. Obviously this
38: level of flexibility isn't required for our trivial example, but is very useful in
39: large enterprise applications.
40: -->
41: <aop:pointcut
42: id="serviceMethod"
43: expression="execution(* com.blog.samples.aop.CalculationService.*(..))"/>
44:
45: <!--
46: <aop:before ... /> is used to specify the advice that should be run before a Pointcut
47: method - invoke the startMonitor method to start timing method execution before the Pointcut
48: pointcut-ref - the point cut reference specifies the point of execution in the code where the
49: advice should be run. In this case its before any public method in the
50: Calculation Service.
51: -->
52: <aop:before
53: method="startMonitor"
54: pointcut-ref="serviceMethod"/>
55:
56: <!--
57: <aop:after ... /> is used to specify the advice that should be run after a Pointcut
58: method - invoke the stopMonitor method to stop timing method execution after the Pointcut
59: pointcut-ref - the point cut reference specifies the point of execution in the code where the
60: advice should be run. In this case its after any public method in the
61: Calculation Service.
62: -->
63: <aop:after
64: method="stopMonitor"
65: pointcut-ref="serviceMethod"/>
66:
67: <!--
68: method - invoke the log method to log method execution metrics after the Pointcut
69: pointcut-ref - the point cut reference specifies the point of execution in the code where the
70: advice should be run. In this case its after any public method in the
71: Calculation Service.
72: -->
73: <aop:after
74: method="log"
75: pointcut-ref="serviceMethod"/>
76:
77: <!--
78: <aop:after-throwing ... /> is used to define the advice to be run after an exception is thrown at a Pointcut.
79: method - invoke the stopMonitor method to stop timing method execution after an exception is thrown at the Pointcut
80: pointcut-ref - the point cut reference specifies the point of execution in the code where the
81: advice should be run. In this case its after any public method in the
82: Calculation Service.
83: -->
84: <aop:after-throwing
85: method="stopMonitor"
86: pointcut-ref="serviceMethod"/>
87:
88: <!--
89: method - invoke the log method to stop timing method execution after an exception is thrown at the Pointcut
90: pointcut-ref - the point cut reference specifies the point of execution in the code where the
91: advice should be run. In this case its after any public method in the
92: Calculation Service.
93: -->
94: <aop:after-throwing
95: method="log"
96: pointcut-ref="serviceMethod"/>
97:
98: </aop:aspect>
99: </aop:config>
100:
101: <!-- ***************************** -->
102:
103: </beans>
Performance Monitor (XML Configuration Approach)
The AOP configuration above uses a PerformanceMonitor class to apply advice at specified Pointcucts. The class is defined below and uses the JAMon API to provide basic performance monitoring functionality to captures and log performance metrics.
1: package com.blog.samples.aop;
2:
3: import java.util.Date;
4: import org.aspectj.lang.JoinPoint;
5: import org.apache.log4j.Logger;
6: import com.jamonapi.Monitor;
7: import com.jamonapi.MonitorFactory;
8:
9: /**
10: * Performance monitor use the Jamon library to provide basic performance
11: * monitoring and logging functionality.
12: *
13: */
14: public class PerformanceMonitor
15: {
16: private static final Logger logger_c = Logger.getLogger(PerformanceMonitor.class);
17: private final String MONITOR = "PERFORMANCE_MONITOR";
18: private Monitor monitor_i;
19:
20: /**
21: * Start monitor
22: */
23: public void startMonitor()
24: {
25: monitor_i = MonitorFactory.start(MONITOR);
26: }
27:
28: /**
29: * Stop monitor
30: */
31: public void stopMonitor()
32: {
33: monitor_i.stop();
34: }
35:
36: /**
37: * get last access
38: *
39: * @return Date
40: */
41: public Date getLastAccess()
42: {
43: return monitor_i.getLastAccess();
44: }
45:
46: /**
47: * get call count
48: *
49: * @return int
50: */
51: public int getCallCount()
52: {
53: return (int) monitor_i.getHits();
54: }
55:
56: /**
57: * get average call time
58: *
59: * @return double
60: */
61: public double getAverageCallTime()
62: {
63: return monitor_i.getAvg() / 1000;
64: }
65:
66: /**
67: * get last call time
68: *
69: * @return double
70: */
71: public double getLastCallTime()
72: {
73: return monitor_i.getLastValue() / 1000;
74: }
75:
76: /**
77: * get maximum call time
78: *
79: * @return double
80: */
81: public double getMaximumCallTime()
82: {
83: return monitor_i.getMax() / 1000;
84: }
85:
86: /**
87: * get minimum call time
88: *
89: * @return double
90: */
91: public double getMinimumCallTime()
92: {
93: return monitor_i.getMin() / 1000;
94: }
95:
96: /**
97: * get total call time
98: *
99: * @return double
100: */
101: public double getTotalCallTime()
102: {
103: return monitor_i.getTotal() / 1000;
104: }
105:
106: /**
107: * log statistics
108: *
109: * @param joinPoint_p
110: */
111: public void log(JoinPoint joinPoint_p)
112: {
113: StringBuffer sb = new StringBuffer();
114:
115: sb.append("\n");
116: sb.append("*======================================");
117: sb.append("\n");
118: sb.append("* PERFORMANCE STATISTICS *");
119: sb.append("\n");
120: sb.append("*======================================");
121: sb.append("\n");
122: sb.append("* Method Name: " + joinPoint_p.getSignature().getName());
123: sb.append("\n");
124: sb.append("* Execution Date: ").append(this.getLastAccess());
125: sb.append("\n");
126: sb.append("* Last Execution Time: ").append(this.getLastCallTime()).append(" sec");
127: sb.append("\n");
128: sb.append("* Service Calls: ").append(((this.getCallCount())));
129: sb.append("\n");
130: sb.append("* Avg Execution Time: ").append(this.getAverageCallTime()).append(" sec");
131: sb.append("\n");
132: sb.append("* Total Execution TIme: ").append(this.getTotalCallTime()).append(" sec");
133: sb.append("\n");
134: sb.append("* Min Execution Time: ").append(this.getMinimumCallTime()).append(" sec");
135: sb.append("\n");
136: sb.append("* Max Execution Time: ").append(this.getMaximumCallTime()).append(" sec");
137: sb.append("\n");
138: sb.append("*======================================");
139:
140: logger_c.info(sb.toString());
141: }
142: }
Line 23 - Method starts monitor. This is called before the service method is invoked.
Line 31 - Method stops monitor. This is called after the service method completes.
Line 41 to 101 - Series of utility methods gather various metrics from the Jamon monitor.
Line 111 - Method logs performance statistics gathered by monitor. The JoinPoint argument provides access to the target object - in this instance we use the JoinPoint to access the name of the target method being invoked.
Spring Configuration (Annotation Driven)
This section shows how AOP can be configured using annotations. You'll notice that this approach is less verbose than the XML approach described earlier. Note that Pointcuts are no longer defined using XML, instead Spring will look for beans annotated with @Aspect and register them as aspects.
1: <beans xmlns="http://www.springframework.org/schema/beans"
2: xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
3: xmlns:aop="http://www.springframework.org/schema/aop"
4: xsi:schemaLocation="http://www.springframework.org/schema/beans
5: http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
6: http://www.springframework.org/schema/aop
7: http://www.springframework.org/schema/aop/spring-aop-3.0.xsd ">
8:
9: <!-- this registers beans annotated with @Aspect -->
10: <aop:aspectj-autoproxy />
11:
12: <!-- Calculation Service bean definition - this is the bean that we want to monitor performance on -->
13: <bean id="calculationService" class="com.blog.samples.aop.CalculationServiceImpl" />
14:
15: <!-- Performance Monitor bean definition - this bean contains performance monitoring logic
16: for starting and stopping the monitoring, logging statistics etc -->
17: <bean id="performanceMonitor" class="com.blog.samples.aop.PerformanceMonitor" />
18:
19: </beans>
Performance Monitor (Annotation Driven)
There are a number of significant differences between the Performance monitor defined below, and the one we defined earlier (using the XML approach). Here AOP is configured using class level meta data in the form of annotations.The @Aspect annotation tells Spring that this class contains advice and should be applied to specified Pointcuts at runtime. The Pointcuts are defined using method level annotations and have the same format as the ones defined earlier.
1: package com.blog.samples.aop;
2:
3: import java.util.Date;
4:
5: import org.aspectj.lang.JoinPoint;
6: import org.aspectj.lang.annotation.After;
7: import org.aspectj.lang.annotation.Aspect;
8: import org.aspectj.lang.annotation.Before;
9: import org.apache.log4j.Logger;
10:
11: import com.jamonapi.Monitor;
12: import com.jamonapi.MonitorFactory;
13:
14: /*
15: * @Aspect tells the Spring framework that this class contains advice that should
16: * be applied to one or more specified Pointcuts at runtime
17: */
18: @Aspect
19: public class PerformanceMonitor
20: {
21: private static final Logger logger_c = Logger.getLogger(PerformanceMonitor.class);
22: private final String MONITOR = "PERFORMANCE_MONITOR";
23: private Monitor monitor_i;
24:
25: /*
26: * @Before tells the Spring framework that this method should be invoked before the specified Pointcut.
27: * The Pointcut expression here is identical to the one we used in the XML configuration example
28: */
29: @Before("execution(* com.blog.samples.aop.CalculationService.dummyServiceMethod())")
30: public void startMonitor()
31: {
32: monitor_i = MonitorFactory.start(MONITOR);
33: }
34:
35: /*
36: * @After tells the Spring framework that this method should be invoked after the specified Pointcut.
37: * The Pointcut expression here is identical to the one we used in the XML configuration example
38: */
39: @After("execution(* com.blog.samples.aop.CalculationService.dummyServiceMethod())")
40: public void stopMonitor()
41: {
42: monitor_i.stop();
43: }
44:
45: /**
46: * get last access
47: *
48: * @return Date
49: */
50: public Date getLastAccess()
51: {
52: return monitor_i.getLastAccess();
53: }
54:
55: /**
56: * get call count
57: *
58: * @return int
59: */
60: public int getCallCount()
61: {
62: return (int) monitor_i.getHits();
63: }
64:
65: /**
66: * get average call time
67: *
68: * @return double
69: */
70: public double getAverageCallTime()
71: {
72: return monitor_i.getAvg() / 1000;
73: }
74:
75: /**
76: * get last call time
77: *
78: * @return double
79: */
80: public double getLastCallTime()
81: {
82: return monitor_i.getLastValue() / 1000;
83: }
84:
85: /**
86: * get maximum call time
87: *
88: * @return double
89: */
90: public double getMaximumCallTime()
91: {
92: return monitor_i.getMax() / 1000;
93: }
94:
95: /**
96: * get minimum call time
97: *
98: * @return double
99: */
100: public double getMinimumCallTime()
101: {
102: return monitor_i.getMin() / 1000;
103: }
104:
105: /**
106: * get total call time
107: *
108: * @return double
109: */
110: public double getTotalCallTime()
111: {
112: return monitor_i.getTotal() / 1000;
113: }
114:
115: /*
116: * @After tells the Spring framework that this method should be invoked after the specified Pointcut.
117: * The Pointcut expression here is identical to the one we used in the XML configuration example
118: */
119: @After("execution(* com.blog.samples.aop.CalculationService.dummyServiceMethod())")
120: public void log(JoinPoint joinPoint_p)
121: {
122: StringBuffer sb = new StringBuffer();
123:
124: sb.append("\n");
125: sb.append("*======================================");
126: sb.append("\n");
127: sb.append("* PERFORMANCE STATISTICS *");
128: sb.append("\n");
129: sb.append("*======================================");
130: sb.append("\n");
131: sb.append("* Method Name: " + joinPoint_p.getSignature().getName());
132: sb.append("\n");
133: sb.append("* Execution Date: ").append(this.getLastAccess());
134: sb.append("\n");
135: sb.append("* Last Execution Time: ").append(this.getLastCallTime()).append(" sec");
136: sb.append("\n");
137: sb.append("* Service Calls: ").append(((this.getCallCount())));
138: sb.append("\n");
139: sb.append("* Avg Execution Time: ").append(this.getAverageCallTime()).append(" sec");
140: sb.append("\n");
141: sb.append("* Total Execution TIme: ").append(this.getTotalCallTime()).append(" sec");
142: sb.append("\n");
143: sb.append("* Min Execution Time: ").append(this.getMinimumCallTime()).append(" sec");
144: sb.append("\n");
145: sb.append("* Max Execution Time: ").append(this.getMaximumCallTime()).append(" sec");
146: sb.append("\n");
147: sb.append("*======================================");
148:
149: logger_c.info(sb.toString());
150: }
151: }
Running the Test Harness
At this point I've covered all the various components and explained how AOP can be configured using both XML and annotations. Its time to run the test harness and see the performance monitor at work. Simply kick off the main method in RunTest.java and you should see the Calculation Service invoked 50 times, with performance metrics logged for each call. For brevity the extract below shows the end of the log.
1: DEBUG: [Apr-16 18:37:12,945] samples.aop.CalculationServiceImpl - Doing some service stuff here...
2: INFO : [Apr-16 18:37:13,493] samples.aop.PerformanceMonitor -
3: *======================================
4: * PERFORMANCE STATISTICS *
5: *======================================
6: * Method Name: dummyServiceMethod
7: * Execution Date: Tue Apr 16 18:37:12 BST 2013
8: * Last Execution Time: 0.063 sec
9: * Service Calls: 49
10: * Avg Execution Time: 0.5139387755102041 sec
11: * Total Execution TIme: 25.183 sec
12: * Min Execution Time: 0.024 sec
13: * Max Execution Time: 0.988 sec
14: *======================================
15: DEBUG: [Apr-16 18:37:13,493] samples.aop.CalculationServiceImpl - Doing some service stuff here...
16: INFO : [Apr-16 18:37:14,176] samples.aop.PerformanceMonitor -
17: *======================================
18: * PERFORMANCE STATISTICS *
19: *======================================
20: * Method Name: dummyServiceMethod
21: * Execution Date: Tue Apr 16 18:37:13 BST 2013
22: * Last Execution Time: 0.548 sec
23: * Service Calls: 50
24: * Avg Execution Time: 0.51462 sec
25: * Total Execution TIme: 25.731 sec
26: * Min Execution Time: 0.024 sec
27: * Max Execution Time: 0.988 sec
Summary
This tutorial has demonstrated how AOP can be used to encapsulate a cross cutting concern, apply it to business logic at runtime, and ensure a clear separation of concerns. Although the performance monitor example is trivial, it demonstrates a realistic use case for AOP and could form the basis for a more complete performance monitoring utility. Full source code is available here for the XML and annotation driven approaches, so feel free to download and play around with it. As always, comments or questions are welcome below.
