What is the fastest, DRYest way to (not) log?

The log4net FAQ asks the question What is the fastest way of (not) logging? It outlines two techniques of logging; I will present one more.

The first technique is the slowest of the three, but contains the least amount of code. The following snippet logs a million times and illustrates the first technique:

   1: for (int i = 0; i < 1000000; ++i)
   2: {
   3:    log.Debug("Number " + i + new Random(DateTime.Now.Millisecond).Next());
   4: }

The big disadvantage of this technique is this: If debug level logging is disabled, then a lot of time is wasted evaluating the current date, getting a random number and concatenating strings. This is because the parameter to the log.Debug method is evaluated before log.Debug is called. A better way to approach would be the following: 

   1: for (int i = 0; i < 1000000; ++i)
   2: {
   3:    if (log.IsDebugEnabled)
   4:    {
   5:       log.Debug("Number " + i + new Random(DateTime.Now.Millisecond).Next());
   6:    }
   7: }

This way, if debug level logging is disabled, the cost of evaluating the parameter to log.Debug is not incurred. However, this more efficient technique is not very DRY, as we have to litter our code with if statements every time we want to log.

Another technique (not mentioned in the FAQ) uses anonymous methods. This third technique achieves more DRYness than the second technique, and is just about as fast. The following code snippet illustrates this third technique:

   1: private delegate string ObjectDelegate(); 
   2:  
   3: private static void LogDebug(ObjectDelegate d)
   4: {
   5:    if(log.IsDebugEnabled)
   6:    {
   7:       log.Debug(d());
   8:    }
   9: }
  10:  
  11: .
  12:  
  13: .
  14:  
  15: for (int i = 0; i < 1000000; ++i)
  16: {
  17:    LogDebug(delegate { return "Number " + i + new Random(DateTime.Now.Millisecond).Next();  });
  18: }
  19:  

How do these techniques match up performance wise? I've written a small console application that measures how long each of these techniques take to not log 1,000,000 times. I ran the application 10 times, and here are the results (in milliseconds):

Slow yet DRY technique Fast, not DRY technique Fast, DRY technique
156 62 78
375 78 78
343 78 78
968 93 78
843 62 78
234 93 62
187 78 78
265 62 78
328 78 62
281 62 78
Share this post: email it! | bookmark it! | digg it! | reddit! | kick it! | live it!
Published Wednesday, June 20, 2007 9:31 PM by trumpi
Filed under: ,

Comments

# re: What is the fastest, DRYest way to (not) log?

Nice!

And for the really really lazy guys who find repeating the delegate keyword too much you can probably replace it with the Func<T> delegate and use a lambda :)

Something like:

public static void LogDebug(Func<String> f)

{

// Do logging stuff

}

LogDebug(() => "Number " + i + new Random(DateTime.Now.Millisecond).Next());

Or while you are at it or getting more lazy, add an extension method so that all your types that brings your LogExtensions class into scope have logging capabilities :

 public static class LogExtensions

   {

       public static void Log(this object o, Func<string> f)

       {

           Console.WriteLine(f());

       }

   }

   class Program

   {

       static void Main(string[] args)

       {

           Program p = new Program();

           p.Log(() => DateTime.Now.ToShortDateString());

       }

   }

 

Although this last one violates the SRP depending on how you look at it.

Thursday, June 21, 2007 1:00 PM by Armand du Plessis

# What is the fastest, DRYest way to (not) log?

You've been kicked (a good thing) - Trackback from DotNetKicks.com

Sunday, June 24, 2007 12:44 AM by DotNetKicks.com

# re: What is the fastest, DRYest way to (not) log?

Armand, this is already deep in C# 3.0 land, while the article was 2.0...

But it's a nice 'n' dry idea.

I have not used the log4net package lately, but surely you can log other things than strings? In which case something like

private delegate T ObjectDelegate<T>();

may be even more appropriate.

Thursday, July 05, 2007 9:51 PM by F Quednau

# Ultracet.

Extracting acetaninophen from ultracet. Ultracet vs vicodin. Lexapro-ultracet-interactions. Ultracet.

Friday, August 08, 2008 7:17 AM by Ultracet and coumadin.