Tracing methods execution time

Question

I am trying to "inject" custom tracing methods in my application.

I want to make it as elegant as possible, without modifying to much of the existing code, and have the possibility to enable / disable it easily.

One solution i could think of would be to create a custom Attribute which i will attach it to the methods i want to trace.

Basic idea:

public class MethodSnifferAttribute : Attribute
{
    private Stopwatch sw = null;

    public void BeforeExecution()
    {
        sw = new Stopwatch();
        sw.Start();
    }
    public void ExecutionEnd()
    {
        sw.Stop();
        LoggerManager.Logger.Log("Execution time: " + sw.ElapsedMilliseconds);
    }
}

public class MyClass
{
    [MethodSniffer]
    public void Function()
    {
        // do a long task
    }
}

Are there any existing .NET attributes that provides callbacks for when a method is called / ended?

Answer 1

Attribute's method are not called unless you call it manually. There are security attributes which are invoked by the CLR but that's beyond the subject of this question and it will not be useful anyway.

There are techniques to rewrite your code at different level. Source code weaving, IL weaving etc.

You need to look at some way to modify the IL and rewrite it for timing the execution. Don't worry, you don't have to write all of that. People have already done it. For example, you can use PostSharp.

Here's an article which provides an example

[Serializable]
[DebuggerStepThrough]
[AttributeUsage(AttributeTargets.Method)]
public sealed class LogExecutionTimeAttribute : OnMethodInvocationAspect
{
    private static readonly ILog Log = LogManager.GetLogger(typeof(LogExecutionTimeAttribute));

    // If no threshold is provided, then just log the execution time as debug
    public LogExecutionTimeAttribute() : this (int.MaxValue, true)
    {
    }
    // If a threshold is provided, then just flag warnning when threshold's exceeded
    public LogExecutionTimeAttribute(int threshold) : this (threshold, false)
    {
    }
    // Greediest constructor
    public LogExecutionTimeAttribute(int threshold, bool logDebug)
    {
        Threshold = threshold;
        LogDebug = logDebug;
    }

    public int Threshold { get; set; }
    public bool LogDebug { get; set; }

    // Record time spent executing the method
    public override void OnInvocation(MethodInvocationEventArgs eventArgs)
    {
        var sw = Stopwatch.StartNew();
        eventArgs.Proceed();
        sw.Stop();
        var timeSpent = sw.ElapsedMilliseconds;

        if (LogDebug)
        {
            Log.DebugFormat(
                "Method [{0}{1}] took [{2}] milliseconds to execute",
                eventArgs.Method.DeclaringType.Name,
                eventArgs.Method.Name,
                timeSpent);
        }

        if (timeSpent > Threshold)
        {
            Log.WarnFormat(
                "Method [{0}{1}] was expected to finish within [{2}] milliseconds, but took [{3}] instead!",
                eventArgs.Method.DeclaringType.Name,
                eventArgs.Method.Name,
                Threshold,
                timeSpent);
       }
}

Note: I've modified the example from the article to use StopWatch instead of DateTime because DateTime isn't accurate.

Answer 2

You can trace method execution time easily with PostSharp (available as NuGet package). Code of custom method-level attribute that doing just that (taken from here):

  [Serializable]
  [DebuggerStepThrough]
  [AttributeUsage(AttributeTargets.Method)]
  public sealed class LogExecutionTimeAttribute : OnMethodInvocationAspect
  {
  private static readonly ILog Log = LogManager.GetLogger(typeof(LogExecutionTimeAttribute));

  // If no threshold is provided, then just log the execution time as debug
  public LogExecutionTimeAttribute() : this (int.MaxValue, true)
  {
  }
  // If a threshold is provided, then just flag warnning when threshold's exceeded
  public LogExecutionTimeAttribute(int threshold) : this (threshold, false)
  {
  }
  // Greediest constructor
  public LogExecutionTimeAttribute(int threshold, bool logDebug)
  {
    Threshold = threshold;
    LogDebug = logDebug;
  }

  public int Threshold { get; set; }
  public bool LogDebug { get; set; }

  // Record time spent executing the method
  public override void OnInvocation(MethodInvocationEventArgs eventArgs)
  {
    var start = DateTime.Now;
    eventArgs.Proceed();
    var timeSpent = (DateTime.Now - start).TotalMilliseconds;

    if (LogDebug)
    {
    Log.DebugFormat(
    "Method [{0}{1}] took [{2}] milliseconds to execute",
    eventArgs.Method.DeclaringType.Name,
    eventArgs.Method.Name,
    timeSpent);
    }

    if (timeSpent > Threshold)
    {
    Log.WarnFormat(
    "Method [{0}{1}] was expected to finish within [{2}] milliseconds, but took [{3}] instead!",
    eventArgs.Method.DeclaringType.Name,
    eventArgs.Method.Name,
    Threshold,
    timeSpent);
    }
  }