Monday, June 09, 2008

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.

2 comments:

  1. You discovered the bastard stack trace from hell :) Seriously: imho the weakest point of Groovy usage, when you really have to crawl through them...

    You might want to try out the 1.6 beta. Haven't tried it myself, it might be better...

    ReplyDelete
  2. FYI You can clean up the stack trace using org.codehaus.groovy.runtime.StackTraceUtils.sanitize(exception).

    ReplyDelete

Please note that this is not a support forum for Tapestry. Requests for help will be deleted. Please subscribe to the Tapestry user mailing list if you are in need of support, or contact me directly for professional (for pay) support.

Spammers: Don't bother. I delete your comments and it's a waste of time for both of us. 垃圾邮件发送者:不要打扰。我删除您的评论和它的时间对我们双方的浪费