An Asynchronous Logger


Last edited by KogAdmin:
syntax error
Mon, 12 Apr 2010 19:02 PDT [diff]

New: I've started a Gitorious project at http://gitorious.org/thoreau, check it out!
 


Abstract


The intent of this article is to analyze a particular design for asynchronous logging, using Hibernate as the persistence mechanism. The design takes into account loose coupling, as usually found amongst the believers of Inversion of Control (also known as Dependency Injection). The design listed here was originally going to be implemented at work, but unbeknownst to me we already had a performance metric gathering solution already written by one of my co-workers in another module. All source in here was written on my own time, using my own computing resources, and makes no attempt to compete with or otherwise detract from my day job. All source is MIT licensed, all documentation is Creative Commons 2 licensed.

The idea is to allow for asynchronous statistics gathering, so that you don't really need to worry about blocking your main thread. The idea of using Hibernate is that you don't really care about the underlying persistence mechanism of the metrics, only that you record them somehow. Using an annotated Hibernate class allows rather arbitrary statistics, insofar as they're annotated. Unfortunately there's no language level enforcement to ensure that your object is indeed mapped/annotated. Perhaps Java 7.

All of the moving parts are easily interchangeable, even to the point where someone might look at the UML and declare that it's been "over designed." Loose collaboration allows better testing, less programming (in the long run) and produces a more robust piece of software. I suppose you could always hack in some raw SQL and distill this down to a single class... The persistence mechanism can be swapped out easily, as can the gathering instrumentation (because you may want to gather different types of stats) and you can also change your write operation factory to output operations that do anything - as long as they implement Callable. The only constant here is that we have an executor that expects Callable objects, although this is called by interface as well, so you can conceivably write your own executor.


Design


The class diagram is as follows (with apologies for my sorry Visio skills):


Statistics UML

AbstractMetricGatherer

This is your instrumentation. The abstract class contains many of the setup operations, and allows you to inject your implementation of your IStatisticsLogger - the combination of your write operation factory and your executor for asynchronous writing. You see that in this case there is an AOP based metric gatherer that, when combined with Spring, allows us to gather metrics about method calls without any modification to our original source. You implement a method interceptor like so:

    /**
     * Intercepts a method call and computes some statistics about it. If we catch an exception in our interception we log
     * it and re-throw it, so as to preserve the line numbers for debugging purposes.
     *
     * @param methodInvocation The {@link org.aopalliance.intercept.MethodInvocation} to be invoked.
     *
     * @return an object representing the result of the method invocation.
     *
     * @throws Throwable if there's an exception in the underlying operation.
     */

    @Override
    public Object invoke(@NotNull final MethodInvocation methodInvocation) throws Throwable
    {
        // We need these for our context.
        Object result = null;
        Exception ex = null;

        final MethodCallStatistic metric = createMethodCallStatistic();

        try
        {
            metric.setOperationName(getMethodName(methodInvocation));
            metric.setOperationStart(getCurrentDate());

            // Call the operation that we've intercepted.
            result = methodInvocation.proceed();

        }
        catch (final Exception e)
        {
            ex = e;
        }
        finally
        {
            metric.setOperationCompletion(getCurrentDate());
            metric.setOperationSuccessful(true);

            // If we caught an exception, make sure we log the failure.
            if (ex != null)
            {
                metric.setOperationSuccessful(false);
                metric.setMetaData(ex.toString());
            }

            // Persist our entity.
            getStatisticsLogger().writeStatistic(metric);

            // Re-throw our exception, if any was caught.
            if (ex != null)
            {
                // It's usually bad practice to throw inside a finally block. But we need this since we're doing some
                // logging on our exceptions via AOP.
                throw ex;
            }
        }

        return result;
    }


where your logic is very simple:
  1. Take the start time
  2. Call "proceed" on the method
  3. If you've caught an exception make sure you nab it for logging, and get ready to pass it back up the call stack
  4. Create your statistic
  5. Tell it to write

With some very fast Spring wiring to set up your AOP, as well as your collaborators, you wind up with metric gathering across method calls free. You can even use the given expression language to mask methods and packages, such that you only get statistics for certain problem areas in your application. If you want to go nuts you could even expose that expression via MBeans or any other mechanism and manipulate the coverage on the fly.


IStatisticsLogger

Your primary collaborator that goes with your AOP gatherer (or other such mechanism). The logger contains both the logic for creating atomic write operations as well as the logic for writing them asynchronously. Pass in your write operation factory that hands you back a callable and you suddenly get stat writing for free. The factory can produce a Hibernate persist, a raw SQL query, writing to a flatfile, SMS messaging, email, smoke signals or even X10 messages - the logger doesn't really care what it does, only that it follows the contract to create a callable that it can call. Each callable is atomic, and contains everything it needs to execute.

Our out-of-the-box implementation is the GenericAsynchronousLogger, which would be sufficient for your needs except that it's generic. This means that to guarantee type safety we have a sort of shallow inheritance where you slap on the MethodCallAsynchronousLogger which has the sole responsibility of creating a concretely typed logger - instead of N you now have something that spits out IMethodCallStatistic implementers. This is literally 5 lines of source, and is only required because there's not really any good way of passing in generic type parameters to Spring (yet).


IWriteOperationFactory

The write operation factory is another mostly shallow abstraction, there to provide loose coupling. The factory is injected with whatever context you need, such as a Hibernate session, JDBC Connection objects or file handles. The concretizations of this class then take this context and inject it into each atomic write operation as needed. In this example we inject our Hibernate session. Later when we call writeStatistic, we wind up shoving an entity into a callable write operation and bam, we get persistence. If you wanted to put some logic in to make sure that the entity being written indeed is annotated, the individual write operations would check to make sure, although this is somewhat useless since Hibernate itself will throw exceptions...

IMethodCallStatistic

The contract for our actual storage entity. Nothing particularly surprising here:

Getting it running


If you check out the Gitorious project (http://gitorious.org/thoreau/instrumentation) you can find the application. There are a pair of unit tests that demonstrate everything you need to wire up your app for metric gathering, but here are the cromulent parts. First you have your set of objects that we're wiring together: our AOPMetricGatherer which we're wiring in, and it's collaborators: a StatisticsLogger and a WriteOperationFactory. There's an executor listed below for testing purposes, but you might actually want to use another executor service, check out http://java.sun.com/javase/6/docs/api/java/util/concurrent/Executors.html for more ideas.

    <bean name="metricGatherer" class="org.epiphanic.instrumentation.performance.AOPMetricGatherer">
        <property name="statisticsLogger" ref="statisticsLogger"/>
    </bean>

    <bean name="statisticsLogger" class="org.epiphanic.instrumentation.performance.MethodCallAsynchronousLogger">
        <property name="messageProcessor" ref="executor"/>
        <property name="writeOperationFactory" ref="writeOperationFactory"/>
    </bean>

    <bean name="writeOperationFactory" class="org.epiphanic.instrumentation.performance.HibernateWriteOperationFactory">
        <property name="sessionFactory" ref="sessionFactory"/>
    </bean>

    <bean name="executor" class="java.util.concurrent.Executors" factory-method="newSingleThreadExecutor"/>


Where sessionFactory is whatever you're using for a session factory. You'll want to add the MethodCallStatistic class to your original session factory so that it knows to be mapped. You'll also most likely not want to use a single thread executor, but for a sample this suffices.

An example of using interception with the new auto-proxy mechanism in Spring follows:

    <bean name="performanceInstrumentationInterceptor" class="org.epiphanic.instrumentation.performance.AOPMetricGatherer">
        <property name="statisticsLogger" ref="statisticsLogger"/>
    </bean>

    <bean name="instrumentedClass" class="org.epiphanic.instrumentation.performance.BoringClassWithInstrumentableMethods"/>

    <bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
      <property name="beanNames" value="instrumentedClass"/>
      <property name="interceptorNames">
        <list>
          <value>performanceInstrumentationInterceptor</value>
        </list>
      </property>
    </bean>


and you get free statistics gathering. Pretty nifty eh?

TBA: UML demonstrating the flow of control


Reporting


Naturally you probably want to know how to read the stats once you have them. There are many ways to get this stat data, and to display it, but perhaps the easiest is to expose a JMX MBean. I know that MBeans aren't exactly pretty, but the UI portion is already done and you wind up writing a minimum of source to obtain a readable "report" of your statistics. If you get really cheeky you can even write your own renderer, or embed some HTML in it (which is arguably horrendous practice).

On the other hand, you can always write some simple JMX logic and shove it into your projects, once again getting that whole "no modification, but cool toys" deal, for Spring has a mechanism for exporting MBeans. Plus, you already have your persistence entity annotated from before, so it's pretty simple to write a small DAO class that does some fetching or some summary, making use of Hibernate's criteria support.

Should you go the MBean route, you get some configuration to go with your JAR that looks roughly like this:

TBA: Spring JMX config

and if your container is anything cool like JBoss (or anything else reasonable) you wind up with your JMX console displaying something that looks like this:

TBA: screenshot


Conclusions


I personally believe that it should be intuitively obvious as to the gains you make by using Inversion of Control in this instance: namely that you get these modules working out of the box. The design is easily tested (TBA: Javadocs?) and fairly simple. If you don't like one implementation you can write it as a secondary library, call it from your primary project and switch out the implementations on the fly - without recompilation or any changes to your original source base. This is loose coupling at its best.

When I first saw IoC, and when I was fresher to object oriented programming, I was never really aware as to why interfaces mattered. It seemed to me that interfaces were equivalent to abstract classes, and thus gained me nothing as there was no callee-side reuse. The transition to interface-based design is definitely one of subtlety, especially if you're coming from a language like C# or C++ where the distinction between a pure contract and a partially defined class somewhat blur.

It's very easy to look at inversion of control and say it's more work, or that it violates encapsulation: after all you're providing setter access to an internal variable, you're exposing state and you're allowing mutation. The irony here is that when you design by contract and use interfaces you're not exposing anything and you're very loosely coupled; when you hard-code your collaborators you're hard-coding behavior, you're coupling yourself to your collaborator. You don't really care what your collaborator is within the context of that object, you really care that it responds to a specific set of messages and parameters. Maybe it's a mock object, maybe it's real, who cares.

The real cost is when you're not familiar with your container, whether it be Spring(.NET), Windsor/Micro Kernel or whatever cheap knockoff MS eventually writes. Setting up all context and wiring things together can be somewhat daunting - refactoring a pre-existing application doubly so. Once you get your system wired together it's very, very handy for configuration.

If you can critique the design with anything more intelligent than "it sucks" or "you suck" feel free to, I'd love to have a running dialog. I hope to have a JAR or two available as soon as time permits, so that you can actually use the design...
There are no comments on this page.
Valid XHTML :: Valid CSS: :: Powered by WikkaWiki