1

I'm using OnMethodBoundryAspect to create a simple logging and execution timing aspect. I would like to create a logger per method. however, if the Logger is not declared as static member it doesn't work. it's impossible to create a logger per method if it's declared as static.

here is my aspect:

[Serializable]
public class MonitorAttribute : OnMethodBoundaryAspect
{
    [NonSerialized]
    private Stopwatch _stopwatch;

    private string _methodName;
    private ILog _log;

    public MonitorAttribute()
    {
    }

    /// <summary>
    /// overrides the method name in the logs
    /// </summary>
    /// <param name="method"></param>
    public MonitorAttribute(string method)
    {
        _methodName = method;
    }

    #region Overrides

    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        if (string.IsNullOrEmpty(_methodName))
            _methodName = method.Name;

        _log = LogManager.GetLogger(_methodName);
    }

    public override void OnEntry(MethodExecutionArgs args)
    {
        _stopwatch = Stopwatch.StartNew();
        _log.InfoFormat("Method {0} called", _methodName);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        _stopwatch.Stop();
        _log.InfoFormat("Method {0} exited successfully. execution time {1} milliseconds", _methodName, _stopwatch.ElapsedMilliseconds);
    }

    public override void OnSuccess(MethodExecutionArgs args)
    {
        _stopwatch.Stop();
        _log.InfoFormat("Method {0} executed successfully. execution time {1} milliseconds", _methodName, _stopwatch.ElapsedMilliseconds);
    }

    #endregion
}
Cœur
  • 37,241
  • 25
  • 195
  • 267
Amr Ellafy
  • 730
  • 8
  • 26

1 Answers1

2

The correct place to initialize the instance of the logger _log would be the RuntimeInitialize method. In your current example you create the logger only during the compile time.

I'd also suggest that initializing a new instance of _stopwatch for each OnEntry is not thread-safe and may cause incorrect results.

You can use a static stopwatch and a MethodExecutionArgs.MethodExecutionTag property to store the current time in the OnEntry. This value will be passed to your OnSuccess and OnExit methods afterwards.

So the modified example may look like this:

[Serializable]
public class MonitorAttribute : OnMethodBoundaryAspect
{
    private static Stopwatch _stopwatch = Stopwatch.StartNew();

    [NonSerialized] private ILog _log;

    private string _methodName;

    public MonitorAttribute()
    {
    }

    /// <summary>
    /// overrides the method name in the logs
    /// </summary>
    /// <param name="method"></param>
    public MonitorAttribute(string method)
    {
        _methodName = method;
    }

    #region Overrides

    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        if (string.IsNullOrEmpty(_methodName))
            _methodName = method.Name;
    }

    public override void RuntimeInitialize(MethodBase method)
    {
        _log = LogManager.GetLogger(_methodName);
    }

    public override void OnEntry(MethodExecutionArgs args)
    {
        _log.InfoFormat("Method {0} called", _methodName);
        args.MethodExecutionTag = _stopwatch.ElapsedMilliseconds;
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        long stopwatchStart = (long) args.MethodExecutionTag;
        _log.InfoFormat("Method {0} exited successfully. execution time {1} milliseconds", _methodName,
            _stopwatch.ElapsedMilliseconds - stopwatchStart);
    }

    public override void OnSuccess(MethodExecutionArgs args)
    {
        long stopwatchStart = (long) args.MethodExecutionTag;
        _log.InfoFormat("Method {0} executed successfully. execution time {1} milliseconds", _methodName,
            _stopwatch.ElapsedMilliseconds - stopwatchStart);
    }

    #endregion
}
AlexD
  • 5,011
  • 2
  • 23
  • 34
  • Thanks for the comprehensive answer! however, your approach to StopWatch generates an incorrect timing. I have a method where which i use Thread.Sleep(2000), however the stopwatch returned 1991. using my code it returns 2001. – Amr Ellafy Sep 06 '13 at 07:57
  • This a strange behavior, in my tests i usually get 2001-2002 ms result with the same code. As alternative, you can also try to store the stopwatch instance in the tag: `args.MethodExecutionTag = Stopwatch.StartNew()`. – AlexD Sep 06 '13 at 08:55