Performance - Lambdas and closures

Whilst performance tuning a recent application, I noticed that the logging was taking an awfully long time, now, whilst this may not come as a surprise in some cases, it came as a surprise being as logging was turned off. Let me explain...

In the application, all BOs use reflection to create a string version of themselves. We were using log4net to do our logging and we were even checking that specific levels of logging were turned on before performing the logging using the simple checks:

    1 private static void WriteToLog(LogLevel logLevel, ILog log, string msg, Exception e)

    2 {

    3     switch (logLevel)

    4     {

    5         case LogLevel.All:

    6         case LogLevel.Trace:

    7             if (log.IsTraceEnabled)

    8             {

    9                 if (e == null) log.Trace(msg);

   10                 else log.Trace(msg, e);

   11             }

   12             break;

   13         case LogLevel.Debug:

   14             if (log.IsDebugEnabled)

   15             {

   16                 if (e == null) log.Debug(msg);

   17                 else log.Debug(msg, e);

   18             }

   19             break;

   20         case LogLevel.Error:

   21             if (log.IsErrorEnabled)

   22             {

   23                 if (e == null) log.Error(msg);

   24                 else log.Error(msg, e);

   25             }

   26             break;

   27         case LogLevel.Fatal:

   28             if (log.IsFatalEnabled)

   29             {

   30                 if (e == null) log.Fatal(msg);

   31                 else log.Fatal(msg, e);

   32             }

   33             break;

   34         case LogLevel.Info:

   35             if (log.IsInfoEnabled)

   36             {

   37                 if (e == null) log.Info(msg);

   38                 else log.Info(msg, e);

   39             }

   40             break;

   41         case LogLevel.Warn:

   42             if (log.IsWarnEnabled)

   43             {

   44                 if (e == null) log.Warn(msg);

   45                 else log.Warn(msg, e);

   46             }

   47             break;

   48         case LogLevel.Off:

   49         default:

   50             break;

   51     }

   52 }

So we were taking all the precautions except the most obvious one: we were creating the msg to log even if we didn't log the msg.

The problem that I was now facing was that we had a generic method for writting the log but the methods that wanted to be called on demand didn't. This is where lambdas and closures came in nice and handy. By creating a lambda and passing in the arguments for creating the message in, this defered the execution of the creation of the message until it was time to write the message:

    1 private static void WriteToLog(LogLevel logLevel, ILog log, Func<string> getMessage, Exception e)

    2 {

    3     switch (logLevel)

    4     {

    5         case LogLevel.All:

    6         case LogLevel.Trace:

    7             if (log.IsTraceEnabled)

    8             {

    9                 if (e == null) log.Trace(getMessage());

   10                 else log.Trace(getMessage(), e);

   11             }

   12             break;

   13         case LogLevel.Debug:

   14             if (log.IsDebugEnabled)

   15             {

   16                 if (e == null) log.Debug(getMessage());

   17                 else log.Debug(getMessage(), e);

   18             }

   19             break;

   20         case LogLevel.Error:

   21             if (log.IsErrorEnabled)

   22             {

   23                 if (e == null) log.Error(getMessage());

   24                 else log.Error(getMessage(), e);

   25             }

   26             break;

   27         case LogLevel.Fatal:

   28             if (log.IsFatalEnabled)

   29             {

   30                 if (e == null) log.Fatal(getMessage());

   31                 else log.Fatal(getMessage(), e);

   32             }

   33             break;

   34         case LogLevel.Info:

   35             if (log.IsInfoEnabled)

   36             {

   37                 if (e == null) log.Info(getMessage());

   38                 else log.Info(getMessage(), e);

   39             }

   40             break;

   41         case LogLevel.Warn:

   42             if (log.IsWarnEnabled)

   43             {

   44                 if (e == null) log.Warn(getMessage());

   45                 else log.Warn(getMessage(), e);

   46             }

   47             break;

   48         case LogLevel.Off:

   49         default:

   50             break;

   51     }

   52 }

And then the calls to the logging could be called as such:

    1 try

    2 {

    3     WriteToLog(LogLevel, log, () => GetEntryMessage(invocation, uniqueIdentifier), null);

    4     returnValue = invocation.Proceed();

    5 }

    6 catch (ThreadAbortException)

    7 {

   10     exitThroughException = false;

   11     throw;

   12 }

   13 catch (Exception e)

   14 {

   15     TimeSpan executionTimeSpan = DateTime.Now - startTime;

   16     WriteToLog(LogLevel, log, () => GetExceptionMessage(invocation, e, executionTimeSpan, uniqueIdentifier), e);

   17     exitThroughException = true;

   18     throw;

   19 }

   20 finally

   21 {

   22     if (!exitThroughException)

   23     {

   24         TimeSpan executionTimeSpan = DateTime.Now - startTime;

   25         WriteToLog(LogLevel, log, () => GetExitMessage(invocation, returnValue, executionTimeSpan, uniqueIdentifier), null);

   26     }

   27     ClearLogContext();

   28 }

   29 

   30 return returnValue;

No need to worry about creating overrides of the logging function to take in the different parameters or creating a master version which handled null arguments.