AOP Separating Cross-cutting Concerns

Question

I'm trying to start taking advantage of Aspect-Oriented programming for repetitive tasks. I'm not sure how to go about separating concerns. I'm using C# and for AOP I'm using Castle.DynamicProxy (using Autofac's InterceptedBy feature), but I'm hoping an answer to this question can be general enough advice to apply to other AOP solutions as well (maybe you can convince me to switch to a different AOP solution).

For example, I have something like the following interceptor that intercepts all method calls to a class. It currently has two concerns: when a method is called, (1) measure how long the call took, and (2) log the name of the method before and after it is called.

public class TimeLoggingInterceptor : IInterceptor
{
    private ILog m_Log;
    public TimeLoggingInterceptor(ILog log)
    {
        m_Log = log;
    }
    public void Intercept(IInvocation invocation)
    {
        // Logging concerns
        string fullMethodName = invocation.TargetType.Name + "." + invocation.MethodInvocationTarget.Name;
        m_Log.Debug(fullMethodName + " started.");

        // Timing concerns
        DateTime beforeStamp = DateTime.UtcNow;

        // Call method
        invocation.Proceed();

        // Timing concerns
        DateTime afterStamp = DateTime.UtcNow;
        TimeSpan callTime = afterStamp - beforeStamp;

        // Logging concerns
        m_Log.Debug(fullMethodName + " finished. Took " + callTime.TotalMilliseconds + "ms.");
    }
}

I have an overwhelming feeling that the timing concerns here (measuring how long the method call took) should be separated from the logging concerns (writing to the log file) because...well, they're separate concerns. I'm thinking of doing something like this, but I'm not sure how to approach ordering or where to put the callTime variable:

public class TimingInterceptor : IInterceptor
{
    private static ThreadLocal<TimeSpan> callTime = new ThreadLocal<TimeSpan>();
    public static TimeSpan CallTime
    {
        get
        {
            if (!callTime.IsValueCreated) throw new InvalidOperationException("callTime was never set");
            return callTime.Value;
        }
    }

    public void Intercept(IInvocation invocation)
    {
        // Timing concerns
        DateTime beforeStamp = DateTime.UtcNow;

        // Call method
        invocation.Proceed();

        // Timing concerns
        DateTime afterStamp = DateTime.UtcNow;
        callTime.Value = afterStamp - beforeStamp;
    }
}
public class LoggingInterceptor : IInterceptor
{
    private ILog m_Log;
    public LoggingInterceptor(ILog log)
    {
        m_Log = log;
    }

    public void Intercept(IInvocation invocation)
    {
        // Logging concerns
        string fullMethodName = invocation.TargetType.Name + "." + invocation.MethodInvocationTarget.Name;
        m_Log.Debug(fullMethodName + " started.");

        // Call method
        invocation.Proceed();

        // Logging concerns
        m_Log.Debug(fullMethodName + " finished. Took " + TimingInterceptor.CallTime.TotalMilliseconds + "ms.");
    }
}

Basically what I'm thinking needs to happen here is that, somehow, TimingInterceptor needs to directly intercept the methods, and then LoggingInterceptor needs to wrap around that.

What approaches do people use to make sure these concerns will happen in the correct order? Do I chain the interceptors, having LoggingInterceptor intercept TimingInterceptor's Intercept method? Or do I put some kind of [InterceptOrder(1|2|3|...)] attribute on the interceptor classes? Or can I put something like [InterceptAfter(typeof(TimingInterceptor))] on LoggingInterceptor?

And is there a better alternative to using a thread-local variable to keep track of the call time? Yes, I'd like this to be thread safe. I'm thinking keeping this variable on the stack might be preferred, but I'm not sure how LoggingInterceptor could get a handle to TimingInterceptor without introducing too much coupling (would be nice to be able to switch out the TimingInterceptor implementation without recompiling LoggingInterceptor).

Answer 1

Have you tried just adding both Interceptors to your proxy and running your code? My understanding is that if a proxy has multiple Interceptors, calling Proceed() in the first interceptor in the chain will actually call the next interceptor, rather than actually performing the invocation.

Answer 2

It is good to try separate concerns in your applications. But concerns cannot have a dependency to another.

It may stay confusions about terminology used in IOC/AOP and global coupling domain. Indeed, concerns in AOP paradigm means an independant code/treatment.

In your case, I can identify "logging concern/aspect" and dependency beetween time measurment/calculator (Start+Stop) and logger.

Your AOP framework should inject only a Logging Aspect/Advice that can depend on logger + time calculator (like a business/domain/functional Stopwath) to work. Ideally, logger and time calculator are behind interfaces and logging aspect should use an IOC container to instantiate logging advice with injected (please by constructor) logger and time calculator.

In this way, logging advice, logging aspect, logger module and time calculator module can be unit test and develop by different team in different projects.

Using a threadlocal/threadstatic or callcontext is often a bad idea and can reflect a design issue.

not : if you use threadstatic/threadlocal, take care about memoryleak/long retention object, threadpool management, asynchronous call (Task), bug hard to detect due to coherent and random style results.