Tracing methods execution time Tracing methods execution time asp.net asp.net

Tracing methods execution time


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.


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);    }  }