Proof-of-concept: log in separate thread, transparently with AspectJ5

Suppose there is a case, when logging tasks grab a lot of processing time/memory or probably another "a lot of", e.g. tens of threads at the same time try to acquire a write-lock on resource(e.g. file) or it might appeared that logging routine is costly because it touches network IO.

So, in either case, we decided to log asynchronously. What we have: thousands of Logger.log() calls spread across the code. One obvious way - digg into 3rd party logger src and change log() behaviour so that each call on it will be wrapped in the "log-task" and forwarded underneath to the thread pool. From first sight it's pretty simple, but from the other one - there are drawbacks:

- changing 3rd party isn't good idea;

- weird impl., because now I must support logging_asynchronuosly_version1_my_impl_of_3rdparty.jar;

- hard to plugg-in/plugg-out;

- biggest one: not a granular implementation, since it encompasses all_ calls to Logger.log(), while one might want apply target behaviour only to a manageable subset of code, e.g. to integration test code.

Anyway, whether someone would argue about points above or no, there is an alternative that hasn't mentioned drawbacks (but certainly has another ones, like any solution).

Lets summarize requirements : impl. should be flexible, pluggable, granular(means no "all-or-nothing" approaches), transparent(no code changes).

The loggers are as following:

public class AnotherLogger extends Logger {
    @Override
    void log() {
        System.out.println("\t\tlogging in " + this.getClass().getCanonicalName());
    }
}

public class Logger {
    void log() {
        try {
            Thread.sleep(1000L);
        } catch (InterruptedException ignore_here) {}
        System.out.println("\t\tlogging in " + this.getClass().getCanonicalName());
    }
}

Their "runtime":

public class LoggerTest {
    @Test
    public void test_LoggerLog() throws Exception {
        test(new Logger());
    }

    @Test
    public void test_LoggerOverridenLog() throws Exception {
        test(new AnotherLogger());
    }

    private void test(Logger logger) throws Exception {
        System.out.println("[" + Thread.currentThread().getName() + "]: about to log()");
        logger.log();
        System.out.println("[" + Thread.currentThread().getName() + "]: after log()");
        Thread.sleep(2000L);
        System.out.println("\ntest done: good bye synchronous logging!");
    }
}

With all that we have next output:

You can see logging occurs in main thread, stuff proceeds in synchronous way.

But very soon this will be refactored with AspecJ5 and its AOP "magic".

Meet the "aspect":

@Aspect
public class WrapLoggingInSeparateThreadTransparently {
    private final ExecutorService executor = Executors.newFixedThreadPool(1);

    /**
     * Catch execution of Logger.log in the context of execution flow of any LoggerTest method;
     * 
     * @param pjp is "reserved stuff" here, aspectj knows about use of "around advice" and
     * will provide method with {@link ProceedingJoinPoint} object on runtime.
    */
    @Around(value = "cflow(within(LoggerTest)) && execution(void Logger.log(..))")
    public void adviceMethod(final ProceedingJoinPoint pjp) throws Exception {
        executor.execute(new Runnable() {
        public void run() {
            try {
                System.out.println("[" + Thread.currentThread().getName() + "]: doing log()");
                // calling "trapped" execution join point;
                pjp.proceed();
               System.out.println("[" + Thread.currentThread().getName() + "]: done log()");
            } catch (Throwable ignore) {}
        }
        });
    }
}

After weiving above logic into the code(at compilation time), we have following output:

You see what have already happened?! Our sequential logging transparently became asynchronous! Logging have done in pool-1-thread-1, while our major flow proceeded in main without waiting for log operation. This is legal: log() is void and hasn't access to any shared state, also actual logging happens in the same order as it would in "normal" case(actually, this is true while the size of thread pool = 1 ;)).

Lets examine "aspect" and respective AOP(aspect oriented programming) therms shortly.

First of all, aspect roughly speaking could be mapped logically to a class, with annotation @Aspect(thanks to 5-th version of AspectJ), by default there is single aspect instance within class loader. Magic string "cflow(execution..." is a "pointcut", pointcut for java is like sql for db. Pointcut in AOP selects/matches/catches/fetches program's "join points"(while sql - rows in db). There are several types of join points: initialization of instance, static initialization of class(along with class members and static blocks), execution/call of a method/constructor and so on. So, join points are recognizable "points" in program! Recognizable by ajc.exe, aspectj compiler, which understands both java and aspectj code, because itself ajc is extension of javac. Last thing - adviceMethod()@Around - this is a routine wich will be called on aspect each time joint point is matched. Such routine is called "advice"(there are also another types of advice: @Before and @After). The reason why I chose @Around - because in this case aspectj provides me with ProceedingJoinPoint object(think of it as a trapped execution flow), and I have a choise: whether to proceed with catched join point calling ProceedingJoinPoin.proceed() or just skip it.

 

There are a lot of what we should know about AOP and its java's implementation - AspecJ5.

See these resources:The AspectJ Programming Guide The AspectJ 5 Development Kit Developer's Notebook

In case you want to start criticize such logging approach, I want warn you against doing that, because core point of the post not in logging approach being used but in AOP possibilities.

Thanks for your time!