How would you refactor this smelly code? (Logging, Copy and Paste, .Net 3.5)

Question

I've got code like this:

Logger logger = new Logger();
System.Diagnostics.Stopwatch stopWatch = new System.Diagnostics.Stopwatch();
logger.LogInformation("Calling SomeObject.SomeMethod at " + DateTime.Now.ToString());
stopWatch.Start();
// This is the method I'm interested in.
SomeResponse response = someObject.SomeMethod(someParam);
stopWatch.Stop();
logger.LogInformation("SomeObject.SomeMethod returned at " + DateTime.Now.ToString());
logger.LogInformation("SomeObject.SomeMethod took " + stopWatch.ElapsedMilliseconds + " milliseconds.");

I need to wrap similar code around a lot more objects and their methods to do some performance profiling. I'm not allowed to use 3rd party plugins or software, etc.

I'd really rather not write this same code around all of these method calls this all of this logging code. How would you refactor this to eliminate some of my coding effort?

If I'm not being very clear, please ask questions in the comments and I will try to clarify.

Thanks for any help!!

Answer 1

Definitely a candidate for AOP. We use PostSharp for this sort of thing. http://www.postsharp.org/

Answer 2

For simplicity sake, you could use generics, like so (off the top of my head):

public T MyLogMethod<T,S>(Func<S, T> someFunction, S someParameter) {}

Func(S,T) where S is the parameter type of the method, and T is the return type.

Answer 3

You can refactor the code to accept a method pointer instance (aka System.Action).

public void CallWithLogTiming (Action theAction)
{
  Logger logger = new Logger();
  System.Diagnostics.Stopwatch stopWatch = new System.Diagnostics.Stopwatch();
  logger.LogInformation("Calling SomeObject.SomeMethod at " + DateTime.Now.ToString());
  stopWatch.Start();

// This is the method I'm interested in.
  theAction();

  stopWatch.Stop();
  logger.LogInformation("SomeObject.SomeMethod returned at " + DateTime.Now.ToString());
  logger.LogInformation("SomeObject.SomeMethod took " + stopWatch.ElapsedMilliseconds + " milliseconds.");
}

Then you can call it by creating a lambda expression. Since myResponse is a captured variable, it will be populated when this Action is run and myResponse will be available for use later in this scope.

SomeResponse myResponse = null;
CallWithLogTiming( () => myResponse = someObject.SomeMethod(someParam) );

Answer 4

I think I implement a timer class which can be used like this:

void test()
{
  foo();
  //timer for the following statements
  using (new MyTimer("Some method"))
  {
    bar();
  }
  baz();
}

The MyTimer class is implemented as follows:

• Contains a stop watch instance, and a message string which identifies the timer
• The constructor starts the stop watch and remember the message string
• The Dispose method stops the stop watch, and logs the message string and the ellapsed time

Answer 5

If you write a class like this (I'm using Java; there could be some stuff that doesn't translate exactly):

public class myProfiler {
    final String method;
    final Logger logger = new Logger();
    final System.Diagnostics.Stopwatch stopWatch = new Stopwatch();
    public myProfiler(method) {this.method = method};
    public void Start() {
     logger.LogInformation("Calling " + method + " at " + DateTime.Now.ToString());
     stopWatch.Start();  
    }
    public void Stop() {
     stopWatch.Stop();
     logger.LogInformation(method + " returned at " + DateTime.Now.ToString());
     logger.LogInformation(method + " took " + stopWatch.ElapsedMilliseconds + " milliseconds.");
    }
}

Then you've reduced the code you need in each method to just

myProfiler profiler = new myProfiler("SomeObject.SomeMethod");
profiler.Start();
...
profiler.Stop();

Answer 6

There is always the PostSharp library that lets you do aspect-oriented code. It lets you do the logging and stopwatch as an attribute, which is cool. It will inject pre and post code in your method as a post-compile step.

Further, you might consider some timer/logger static methods like this to wrap the code you want to time/log:

Timer.LogExecutionTime("SomeObject.SomeMethod", () =>
{
    Logger.LogBeforeAndAfter("SomeObject.SomeMethod", () =>
    {
        SomeResponse response = someObject.SomeMethod(someParam);
    }
});

Answer 7

You could make the syntax a little cleaner with some simple extension methods on Logger, this requires no additional assemblies then what you already have and you can plug it in right away. And it is reusable, if you are going to do this a bunch of times throughout your code.

public static class LoggerExtentions
{
    public static void StartTimerLogInformation(this Logger logger, Stopwatch stopWatch, string method)
    {
        stopWatch.Reset();
        stopWatch.Start();
        logger.LogInformation(string.Format("Calling {0} at {1}", method, DateTime.Now.ToString()));
    }        

    public static void StopTimerLogInformation(this Logger logger, Stopwatch stopWatch, string method)
    {
        stopWatch.Stop();
        logger.LogInformation(string.Format("{0} returned at {1}", method, DateTime.Now.ToString()));
        logger.LogInformation(string.Format("{0} took {1} milliseconds", method, stopWatch.ElapsedMilliseconds));
        stopWatch.Reset();
    }
}

then you could just use this code in replacement of the code that you have in your original post

Logger logger = new Logger();
Stopwatch stopWatch = new Stopwatch();
logger.StartTimerLogInformation(stopWatch, "SomeObject.SomeMethod");
SomeResponse response = someObject.SomeMethod(someParam);
logger.StopTimerLogInformation(stopWatch, "SomeObject.SomeMethod");

Answer 8

How about you inherit the timer class on all of your objects?