Trace Method Runtime

Question

I am trying to "embed" custom trace methods in my application.

I want to make it as elegant as possible, without modifying most of the existing code, and be able to easily enable / disable it.

One solution I could think of is to create a custom Attribute that I will attach to the methods I want to track.

Main 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 provide callbacks on method invocation / termination?

Answer 1

The attribute method is not called unless you name it manually. There are security attributes that call the CLR, but this is beyond the scope of this question, and in any case it will be useless.

There are ways to rewrite code at a different level. Source code pairing, IL weaving, etc.

You need to look at some way to change the IL and rewrite it to synchronize execution. Do not worry, you do not need to write all this. People have already done this. For example, you can use PostSharp .

Here's an article that gives 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 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 changed the example from the article to use StopWatch instead of DateTime , because DateTime not accurate.

Answer 2

You can easily trace the execution time of a method using PostSharp (available as a NuGet package). The code for a custom attribute of the method level that does 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 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); } }