Grails Plumbing: Spring AOP Interceptors

On my most recent Grails project we where tasked to get execution times on some methods that were suspected of running a bit long. The quick and easy (but kind of crude) way to do this would be to set a start time at the beginning of the method, and end time at the end, and log the deltas. If you have to do this on more than one method it quickly becomes tedious and starts to really clutter your code base. Luckily, Grails is built upon Spring, and Spring just happens to have a buried gem that does just what we needed: PerformanceMonitorInterceptor.

So today we are going to go over a few AOP Interceptors that are available in Spring that you can use in your Grails application as well. We will show 4 Interceptors that all use AOP to wrap method-level calls at a given pointcut. There is an assumption that the basics of AOP are understood, go here for an overview to Spring AOP.
Along the way we’ll additionally touch on configuring Spring AOP with the Spring Bean Builder and also how to configure a Log4J Daily Rolling File Appender, just for fun.

The sample app for this post can be found here and consists of a single controller and a Service class.

Spring AOP Interceptors:

All are in the org.springframework.aop.interceptor package.

  • SimpleTraceInterceptor
  • PerfomanceMonitorInterceptor
  • ConcurrencyThrottleInterceptor
  • DebugInterceptor

The basics to set each of these up in Grails is pretty simple, and is all done through a few lines of configuration. The same steps can be applied across all four of these interceptors, with some slight variation.

Let’s first look at the the SimpleTraceInterceptor. This interceptor is really nice if you want to add a basic log message that marks the entry and exit of each method call.

NOTE: Because Spring AOP is proxy based (using CGLIB), only calls into the object will be logged. Internal method calls will not be logged because they do not go through the proxy.

Since all of these interceptors use Spring AOP, we need to add the following to our resources.groovy file located in grails-app/conf/spring.

	beans = {
		xmlns aop:"http://www.springframework.org/schema/aop"   //[1]

		aop {
			config("proxy-target-class":true) {  //[2]
    			pointcut(id:"interceptorPointcut", expression:"execution(* grailsee..*Service.*(..))") //[3]
				advisor( 'pointcut-ref': "interceptorPointcut", 'advice-ref':"simpleTraceInterceptorAdvice") //[4]
			}
		}

		simpleTraceInterceptor(org.springframework.aop.interceptor.SimpleTraceInterceptor) { //[5]
			loggerName = "grailsee.SimpleTraceInterceptor"
		}

	}

[1] brings in the namespace and schema in for the Spring AOP to use in our bean builder

[2] Spring AOP will use the CGLIB proxying around our Grails classes so adding the “proxy-target-class:true” attribute is optional and has no impact on the AOP code. Out of the box Grails uses the CGLIB library in order to proxy actual classes instead of interfaces.

[3] is the actual AOP pointcut (the method signatures you want you intercepter to be applied to). In this case we want to apply it to all of the Services in the package and sub-packages that starts with ‘grailsee’.

[4] is the AOP advisor where we wire up our pointcut with our advice which is shown in [5].

[5] is the advice bean that represents the intercepter that we want to use. In addition we are overriding the loggerName that will be used to log the interceptors messages, which I will show next.

Setting Up A Daily Rolling File Appender For Your Interceptors

I typically do this type of logging to a separate log file. The output from these interceptors is usually used for analysis during development time, so having the output contained to it’s own file can be useful, and you don’t have to deal with contaminating you main log file.
Grails gives you 4 log4j appenders out of the box for free (console, file, rollingFile, jdbc). However you can use any log4j appender you want. So for this example we will add a daily rolling file appender that will create a new log file for our intercepters logs statements for every day it it runs.

Find the Config.groovy file under grails-app/conf/ directory and locate the log4j closure.

	import org.apache.log4j.DailyRollingFileAppender //[1]
	import org.apache.log4j.PatternLayout
	
	log4j = {
		def loggingRoot = System.getProperty('user.dir') // [2]
		
		appenders {
			def stdPattern = new PatternLayout(conversionPattern: '%d [%t] %-5p %c{2} %x - %m%n') //[3]
	    	console name:'stdout', layout: stdPattern //[4]
			appender new DailyRollingFileAppender(  //[5]
				name:'simpleTrace', 
				layout: stdPattern, 
				datePattern: "'.'yyyy-MM-dd", 
				file:"${loggingRoot}/simpleTrace.log"
			)
	    }
	
		trace simpleTrace : 'grailsee.SimpleTraceInterceptor' //[6]
	}

[1] add these imports at the top of your Config.groovy file.

[2] creates a directory root we want our log files to write too. In this case it will write to the projects root directory.

[3] creates the pattern layout you want your log fils to write out to.

[4] creates a console appender named ‘stdout’ with the pattern from [3]. NOTE: ‘stdout’ is the default appender name for grails.

[5] creates the DailyRollingFileAppender, named ‘simpleTrace’, that will rotate daily and be log to the simpleTrace.log file under the projects root directory.

[6] wire up the logger we assigned to our simpleTraceInterceptor to our ‘simpleTrace’ appender with a log level of TRACE.

So when we run the project and execute some code one of our services, we will get output in our “simpleTrace.log” file that looks like this:

	2010-10-03 14:34:54,864 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'getMetaClass' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]
	2010-10-03 14:34:54,866 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'getMetaClass' of class [grailsee.FooService]
	2010-10-03 14:34:54,866 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'getMetaClass' of class [grailsee.FooService]
	2010-10-03 14:34:54,866 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'getMetaClass' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]
	2010-10-03 14:34:54,867 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'getMetaClass' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]
	2010-10-03 14:34:54,867 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'getMetaClass' of class [grailsee.FooService]
	2010-10-03 14:34:54,867 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'getMetaClass' of class [grailsee.FooService]
	2010-10-03 14:34:54,867 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'getMetaClass' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]
	2010-10-03 14:34:54,867 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'go' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]
	2010-10-03 14:34:54,893 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Entering method 'go' of class [grailsee.FooService]
	2010-10-03 14:34:54,908 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'go' of class [grailsee.FooService]
	2010-10-03 14:34:54,909 [http-8080-1] TRACE grailsee.SimpleTraceInterceptor  - Exiting method 'go' of class [grailsee.FooService$$EnhancerByCGLIB$$daa6eed3]

As you can see we are intercepting every method call into the FooService which is in the ‘grailsee’ package. You will also notice that we are getting all of the metaClass, and proxy calls logged as well. For now you can do some grep-fu on the log files to weed out the noise or you you can look at applying the pointcuts using the AspectJ annotations.

Now that we know how to set up the SimpleTraceIntercepter lets see what the others look like. The same pointcut will be used, we are just changing the advice and the advice-ref in the advisor. We will also create and new DailyRollingFileAppender for each interceptor.

DebugInterceptor

The DebugInterceptor extends the SimpleTraceIntercepter. It give you log statements at the entry and exit point of each method call but it also give you the full signature of the method and a count of the number of times the intercepter is called. The count is incremented on method entry and decremented on method exit.

Here’s the resources.groovy

	beans = {
		xmlns aop:"http://www.springframework.org/schema/aop"
		
		aop {
			config("proxy-target-class":false) {
				pointcut(id:"interceptorPointcut", expression:"execution(* grailsee.*Service.*(..))")
				advisor( 'pointcut-ref': "interceptorPointcut", 'advice-ref':"debugInterceptorAdvice") 
			}
		}
		
		debugInterceptorAdvice(org.springframework.aop.interceptor.DebugInterceptor)
		
	}

Here’s the Config.groovy for logging

	appenders {
		def stdPattern = new PatternLayout(conversionPattern: '%d [%t] %-5p %c{2} %x - %m%n')
    	        console name:'stdout', layout: stdPattern
		appender new DailyRollingFileAppender(
			name:'debugInterceptor', 
			layout: stdPattern, 
			datePattern: "'.'yyyy-MM-dd", 
			file:"${loggingRoot}/debugInterceptor.log"
		)
       }

       trace debugInterceptor : 'org.springframework.aop.interceptor.DebugInterceptor', additivity:false

Output for debugInterceptor.log

	2010-10-05 09:29:23,596 ...  - Entering ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=1
	2010-10-05 09:29:23,598 ...  - Entering ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService]; count=2
	2010-10-05 09:29:23,598 ...  - Exiting ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService]; count=2
	2010-10-05 09:29:23,598 ...  - Exiting ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=1
	2010-10-05 09:29:23,599 ...  - Entering ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=3
	2010-10-05 09:29:23,599 ...  - Entering ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService]; count=4
	2010-10-05 09:29:23,599 ...  - Exiting ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService]; count=4
	2010-10-05 09:29:23,599 ...  - Exiting ReflectiveMethodInvocation: public groovy.lang.MetaClass grailsee.FooService.getMetaClass(); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=3
	2010-10-05 09:29:23,599 ...  - Entering ReflectiveMethodInvocation: public java.lang.String grailsee.FooService.go(java.lang.Object); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=5
	2010-10-05 09:29:23,621 ...  - Entering ReflectiveMethodInvocation: public java.lang.String grailsee.FooService.go(java.lang.Object); target is of class [grailsee.FooService]; count=6
	2010-10-05 09:29:28,636 ...  - Exiting ReflectiveMethodInvocation: public java.lang.String grailsee.FooService.go(java.lang.Object); target is of class [grailsee.FooService]; count=6
	2010-10-05 09:29:28,638 ...  - Exiting ReflectiveMethodInvocation: public java.lang.String grailsee.FooService.go(java.lang.Object); target is of class [grailsee.FooService$$EnhancerByCGLIB$$c87615b]; count=5

PerfomanceMonitorInterceptor

This can come in pretty handy when you want to do some runtime profiling with out a lot of overhead, or complicated and expensive tooling.

resources.groovy

	beans = {
		xmlns aop:"http://www.springframework.org/schema/aop"   //[1]
		
		aop {
			config("proxy-target-class":true) {  //[2]
    			pointcut(id:"interceptorPointcut", expression:"execution(* grailsee..*Service.*(..))") //[3]
				advisor( 'pointcut-ref': "interceptorPointcut", 'advice-ref':"preformanceMonitoringInterceptorAdvice") [4]	
			}
		}
		
		preformanceMonitoringInterceptorAdvice(org.springframework.aop.interceptor.PerformanceMonitorInterceptor, true){
			loggerName = "grailsee.performanceMonitor"
		}
		
	}

Config.groovy

	def loggingRoot = System.getProperty('user.dir')
    appenders {
		def stdPattern = new PatternLayout(conversionPattern: '%d [%t] %-5p %c{2} %x - %m%n')
    	console name:'stdout', layout: stdPattern
		appender new DailyRollingFileAppender(
			name:'performanceMonitor',
			layout: stdPattern,
			datePattern: "'.'yyyy-MM-dd",
			file:"${loggingRoot}/performanceMonitor.log"
		)
    }

	trace performanceMonitor : 'grailsee.performanceMonitor'

Output in performanceMonitor.log

2010-10-03 16:04:00,852 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.getMetaClass': running time (millis) = 0
2010-10-03 16:04:00,853 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.getMetaClass': running time (millis) = 3
2010-10-03 16:04:00,855 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.getMetaClass': running time (millis) = 0
2010-10-03 16:04:00,855 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.getMetaClass': running time (millis) = 0
2010-10-03 16:04:00,893 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.go': running time (millis) = 13
2010-10-03 16:04:00,895 [http-8080-1] TRACE grailsee.performanceMonitor  - StopWatch 'grailsee.FooService.go': running time (millis) = 40

You see that now we get the execution times in milliseconds for each method call.

ConcurrencyThrottleInterceptor

This interceptor is a bit different that the others in that it allows us to set the maximum number of concurrent calls to the methods under the pointcut.

Per the JavaDoc:

“Can be applied to methods of local services that involve heavy use of system resources, in a scenario where it is more efficient to throttle concurrency for a specific service rather than restricting the entire thread pool (e.g. the web container’s thread pool).”

In the resources.groovy we set the thread limit to 2, so any thread after that will be blocked. You probably want to be very careful with this one.

	beans = {
		aop {
			config("proxy-target-class":true) {
				pointcut(id:"interceptorPointcut", expression:"execution(* grailsee..*Service.*(..))")
				advisor( 'pointcut-ref': "interceptorPointcut", 'advice-ref':"concurrencyThrottleInterceptor") 
			}
		}
	
		concurrencyThrottleInterceptor(org.springframework.aop.interceptor.ConcurrencyThrottleInterceptor) {
			concurrencyLimit = 2
		}
	}

In the Config.groovy we continue with our DailiyRollingFileAppender and use the interceptors logger.

	appenders {
		def stdPattern = new PatternLayout(conversionPattern: '%d [%t] %-5p %c{2} %x - %m%n')
		console name:'stdout', layout: stdPattern
		appender new DailyRollingFileAppender(
			name:'concurrancyThrottle',
			layout: stdPattern,
			datePattern: "'.'yyyy-MM-dd",
			file:"${loggingRoot}/concurrancyThrottle.log"
		)
	}

	trace concurrancyThrottle : 'org.springframework.aop.interceptor.ConcurrencyThrottleInterceptor', additivity:false

Output for concurrancyThrottle.log

2010-10-04 15:30:23,002 [http-8080-3] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Entering throttle at concurrency count 0
2010-10-04 15:30:23,003 [http-8080-2] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Entering throttle at concurrency count 1
2010-10-04 15:30:23,010 [http-8080-1] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking
2010-10-04 15:30:23,011 [http-8080-2] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking
2010-10-04 15:30:23,011 [http-8080-3] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking
2010-10-04 15:30:23,031 [http-8080-4] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking
2010-10-04 15:34:02,072 [http-8080-5] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking
2010-10-04 15:34:27,139 [http-8080-6] DEBUG interceptor.ConcurrencyThrottleInterceptor  - Concurrency count 2 has reached limit 2 - blocking

With only a few lines of configuration, these built in Spring interceptors can help you quickly gain some insight to your Grails project.
While I probably would not recommend deploying these to production, they have proven useful in a development environment for me on more than one occasion. Also don’t forget all that Spring has to offer during your Grails development.

One thought on “Grails Plumbing: Spring AOP Interceptors

  1. Vinay Samudre says:

    Nice Post,

    These are the things on which more documentation should be available with grails. Fact that grails is built on great foundation of Spring and Spring can be easily configured is a strength of grails should be stressed, this post did exactly that.

    Keep up the good work.

  2. JerryB says:

    You have a typo in your first code block.

    simpleTraceInterceptor bean [5] should be named simpleTraceInterceptorAdvice to match advice-ref in [4]

  3. Ganeshan says:

    Nice one – Thanks for Posting this – Very Useful

    1. Ganeshan says:

      log4j:ERROR Appender debugInterceptor not found configuring logger org.springframework.aop.interceptor.DebugInterceptor
      …….Error

      I am getting the below error when i run the application –

      appenders {
      def stdPattern = new PatternLayout(conversionPattern: ‘%d [%t] %-5p %c{2} %x – %m%n’)
      console name:’stdout’, layout: stdPattern
      appender new DailyRollingFileAppender(
      name:’simpleTrace’,
      layout: stdPattern,
      datePattern: “‘.’yyyy-MM-dd”,
      file:”${loggingRoot}/simpleTrace.log”
      )
      }
      trace ‘grails.app’, ‘grailsee.traceLogger’
      trace debugInterceptor : ‘org.springframework.aop.interceptor.DebugInterceptor’,additivity:false

Leave a Reply

Your email address will not be published. Required fields are marked *

*

*