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!!

Pestalozzi

If this were Java, I'd suggest AspectJ. Is there an equivalent for .Net? – Manlove

There is something kinda similar for .Net, but I probably wouldn't be allowed to use it. – Pestalozzi

Answer 1

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

Pellegrini

That's pretty sexy. Will probably confuse the hell out of my poor ex-Java colleagues. lol – Pestalozzi

That is pretty cool...confuses the hell out of me...what exactly are you doing there? :) – Thessalonian

What does the () mean in your call sample? Does it just mean you're calling the lambda block without passing anything into it? – Pestalozzi

The parens are not required in lambda expressions with 1 parameter, they are required in lambda expressions with 0, 2 or more parameters. – Pellegrini

I'm curious to try this, but can't get it working...David can you edit with actual code? I keep getting errors about Action requiring a generic parameter... – Thessalonian

Nevermind...must have been Snippet Compiler getting confused...very slick, David. – Thessalonian

The only thing you might add to this would be wrap the action in a try / catch and log any exceptions? Certainly a valid logging operation. – Drag

I believe this is called the "execute around" idiom, isn't it? – Manlove

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.

Thessalonian

Answer 3

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

Pelagic

I like this. Simple and understandable. +1 – Pellegrini

Answer 4

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

Cote

Thanks Robert, but I'm not allowed to use 3rd party code right now. – Pestalozzi

I'd say it's worth asking your employer about. It's free and doesn't require anything extra on the users' end. It just adds extra code in during the compilation step., and it makes this sort of thing as simple as adding an attribute to a method. If nothing else, you could just use it on your own local copy and make sure all traces are removed before checking in the code. Pain in the ass, but it'll solve your problem. – Cockaleekie

Well, I'm certainly going to start playing with postsharp at home! :) – Pestalozzi

Answer 5

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

Septivalent

Answer 6

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

Fatigued

Answer 7

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

Admonition

Answer 8

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

Gargoyle

Answer 9

What i like to do in these cases is to implement my timers using the Disposable pattern; you'll be guaranteed correct cleanup and logging in case of an error:

    public class Timer : IDisposable
    {
        Logger logger = new Logger();
        Stopwatch stopWatch = new Stopwatch();

        public Timer()
        {
            calledFunc = CalledFunc;
            logger.LogInformation("Calling SomeObject.SomeMethod at " +
                DateTime.Now.ToString());
            stopWatch.Start();
        }

        // Dispose() calls Dispose(true)
        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }
        // NOTE: Leave out the finalizer altogether if this class doesn't 
        // own unmanaged resources itself, but leave the other methods
        // exactly as they are. 
        ~Timer()
        {
            // Finalizer calls Dispose(false)
            Dispose(false);
        }
        // The bulk of the clean-up code is implemented in Dispose(bool)
        protected virtual void Dispose(bool disposing)
        {
            if (disposing)
            {
                // free managed resources
                stopWatch.Stop();
                logger.LogInformation("SomeObject.SomeMethod returned at " +
                    DateTime.Now.ToString());
                logger.LogInformation("SomeObject.SomeMethod took " +
                    stopWatch.ElapsedMilliseconds + " milliseconds.");
            }
            // free native resources if there are any.
        }
    }

Then you use the timer like this:

using (var t = new Timer())
{
   // your code
}

---

Of course you can pass args to the timer (method name, logger, etc) in order to customize what's happening in the setup and dispose

Huxham