Measure method execution time using an attribute (.net core)

Question

I'm interested in measuring the time it takes to execute particular methods.

I was thinking it would be really convenient to do this using a Custom Attribute instead of littering methods with code to start/stop stopwatch and sending to logger. If I could decorate the method in question using an attribute, that'd be really convenient!

I was able to create a Custom Attribute following this article: https://docs.microsoft.com/en-us/dotnet/standard/attributes/writing-custom-attributes

Like so:

public class MonitorExecutionTime : Attribute
{
    private Stopwatch measureExecution;

    // Start measuring on instantiation
    public MonitorExecutionTime()
    {
        measureExecution = new Stopwatch();
        measureExecution.Start();
    }

    // how do I hook into end invoke?
    public MethodHasEnded()
    {

        measureExecution.Stop();
        TimeSpan timeSpan = measureExecution.Elapsed;

        Console.WriteLine("Time: {0}h {1}m {2}s {3}ms", timeSpan.Hours, timeSpan.Minutes, timeSpan.Seconds, timeSpan.Milliseconds);
    }
}

But I'm not sure how to "capture" the being invoke and end invoke points of execution in order to Start the stopwatch and Stop the stopwatch (to measure the time and log it).

Has anyone took this approach in a .net core app? Thanks in advance for any pointers!

Answer 1

Attributes aren't called in runtime. But you can use library like Fody for assembly weaving - to add code automatically after your assembly is compiled into method marked with your custom attribute.

In fact, there is already an implementation like what you want to achieve - Method Timer

Here is how it works (copy/paste from documentation). Your code:

public class MyClass
{
    [Time]
    public void MyMethod()
    {
        //Some code u are curious how long it takes
        Console.WriteLine("Hello");
    }
}

What is actually compiled into final assembly

public class MyClass
{
    public void MyMethod()
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            //Some code u are curious how long it takes
            Console.WriteLine("Hello");
        }
        finally
        {
            stopwatch.Stop();
            Trace.WriteLine("MyClass.MyMethod " + stopwatch.ElapsedMilliseconds + "ms");
        }
    }
}

You can write your custom interceptor code to avoid using Trace.WriteLine and do logging the way you want it.

Answer 2

Attributes in .NET are not wrappers, so you can't use them in that way. You must use a method call wrapper, for example:

public class Service : IService
{
    public void Exec() {
        Wrap("Method Exec", () => {
            // do something usefull
        });
    }

    private void Wrap(string message, Action action)
    {
        var watch = Stopwatch.StartNew();
        try
        {
            action();
        }
        finally
        {
            watch.Stop();
            Console.WriteLine($"{message} executed in {watch.ElapsedMilliseconds} ms");
        }
    }
}

If you want to wrap all methods of class or interface, you should look at aspect-oriented programming, for example in this article: https://www.c-sharpcorner.com/article/aspect-oriented-programming-in-c-sharp-using-dispatchproxy/

Answer 3

@Igore-goyda - your post sent me along the path to what I needed. In summary for others - there are two ways to intercept methods and run some custom processing. Either via a proxy or using an IL rewriter.

I found this article excellent at explaining: http://jeffbelback.me/posts/2015/06/01/principles-of-aop/

I decided the Proxy method would work best for me (didn't like the notion of my code being modified after compilation), and was able to implement a suitable solution using Autofac following this article: https://nearsoft.com/blog/aspect-oriented-programming-aop-in-net-core-and-c-using-autofac-and-dynamicproxy/

The Autofac documentation also helped me out: https://autofaccn.readthedocs.io/en/latest/advanced/interceptors.html?highlight=proxy