Inaccurate performance logging of async method using StopWatch inside PostSharp MethodInterceptionAspect

Question

I've created a PostSharp aspect which is supposed to log the execution time of any method I use it on.

However, it doesn't seem to be working as I expected, with sw.ElapsedMilliseconds always being between 0 and 3 milliseconds.

[Serializable]
[AttributeUsage(AttributeTargets.Method)]
public sealed class PerfLogAttribute : MethodInterceptionAspect
{
    public override void OnInvoke(MethodInterceptionArgs args)
    {
        var sw = new Stopwatch();
        sw.Start();

        args.Proceed();

        sw.Stop();

        log.Debug(sw.ElapsedMilliseconds);
    }
}

Using it like this:

[PerfLog]
public async Task<bool> DoSomethingAsync() {
    // Adding a delay to test (or call database async)
    await Task.Delay(5000);
    return true;
}

Answer 1

As @Christian.K says, you are intercepting just the method which is instantiating the async task, not the async task itself. You are also using Method Interception, which does the job, but it is not exactly the pattern you need as you don't really need to intercept the method execution. You just need to wrap the method.

Your case is actually written in the documentation at http://doc.postsharp.net/async-methods#apply-to-state-machine.

The profiling aspect:

[Serializable]
public class ProfilingAttribute : OnMethodBoundaryAspect
{
    public override void OnEntry( MethodExecutionArgs args )
    {
        Stopwatch sw = Stopwatch.StartNew();
        args.MethodExecutionTag = sw;
    }

    public override void OnExit( MethodExecutionArgs args )
    {
        Stopwatch sw = (Stopwatch) args.MethodExecutionTag;
        sw.Stop();
        Console.WriteLine( "Method {0} executed for {1}ms.",
                           args.Method.Name, sw.ElapsedMilliseconds );
    }
}

Application:

[Profiling( ApplyToStateMachine = true )]
public async Task TestProfiling()
{
    await Task.Delay( 1000 );
    Thread.Sleep( 1000 );
}

This will not work in PostSharp 4.2 if you are using it with Express License, but it will in PostSharp 4.3, which is available for download at https://www.postsharp.net/downloads/postsharp-4.3.

More about profiling can be found in the PostSharp.Samples.Profiling example at http://samples.postsharp.net/.