Using Groovy for IoC Service Decorators

Continuing with my experiments with Groovy, I took a pass at writing a service decorator in Groovy. In Tapestry, the RequestHandler service is the primary execution path; everything filters through it. It's an extensible service, based on the pipeline pattern, so I could contribute a filter into the service, but instead I wrote a decorator around the service.

    def decorateRequestHandler(service, Logger logger)
    {
        {request, response ->
            def start = System.nanoTime()

            def result = service.service(request, response)

            def elapsed = System.nanoTime() - start

            logger.info(String.format("Request time: %5.3f s -- %s", elapsed * 10E-9d, request.path))

            return result
        } as RequestHandler
    }

Tapestry's naming convention is that a module class method named decorateXXX is a decorator for service XXX. The service implementation is passed in. The return value must be the same type as the service (that is, implement the service's interface). Again, we use a closure in Groovy as an easy alternative to an inner class in Java. The code here logs the elapsed time (in seconds) for the request.

What's interesting is just how much gets into the stack trace:

 at org.apache.tapestry5.internal.services.CheckForUpdatesFilter.service(CheckForUpdatesFilter.java:106)
 at $RequestHandler_11a6ead473a.service($RequestHandler_11a6ead473a.java)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:86)
 at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:230)
 at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:912)
 at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:756)
 at org.codehaus.groovy.runtime.InvokerHelper.invokePojoMethod(InvokerHelper.java:766)
 at org.codehaus.groovy.runtime.InvokerHelper.invokeMethod(InvokerHelper.java:754)
 at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.invokeMethodN(ScriptBytecodeAdapter.java:170)
 at com.nfjs.hls.blog.services.AppModule$_decorateRequestHandler_closure2.doCall(AppModule.groovy:49)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:86)
 at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:230)
 at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:248)
 at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:756)
 at groovy.lang.Closure.call(Closure.java:292)
 at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:48)
 at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:72)
 at $Proxy147.service(Unknown Source)
 at $RequestHandler_11a6ead4732.service($RequestHandler_11a6ead4732.java)

In this view, $RequestHandler_11a6ead4732 is a Tapestry runtime fabricated class, the proxy for the service. $Proxy147 is a JDK dynamic proxy which is eventually hooked up to the closure code. The service parameter (to the decorateRequestHandler) is the instance of CheckForUpdatesFilter.

What looks like a simple method invocation turns into several levels of indirection through the Closure and MetaClass code, and then ultimately a reflective method invocation before it picks back up with the first filter in the pipeline (CheckForUpdatesFilter).

This is not especially troubling; I suspect it would be all but impossible to measure the "extra" time the Groovy code takes (vs. an equivalent Java implementation). Still, this could easily add up inside a tight loop, such as the rendering state machine built into Tapestry components. Certainly Merlyn was having performance issues with his visual processing application.