[Source: https://geekswithblogs.net/EltonStoneman]
The venerable log4net library enables cheap instrumentation with configured logging levels, so logs are only written if the log call is on or above the active level. However, the evaluation of the log message always takes place, so there is some performance hit even if the log is not actually written. You can get over this by using delegates for the log message, which are only evaluated based on the active log level:
public static void Log(LogLevel level, Func<string> fMessage)
{
if (IsLogLevelEnabled(level))
{
LogInternal(level, fMessage.Invoke);
}
}
Making the delegate call with a lambda expression makes the code easy to read, as well as giving a performance saving:
Logger.Log(LogLevel.Debug,
=> string.Format("Time: {0}, Config setting: {1}",
DateTime.Now.TimeOfDay,
ConfigurationManager.AppSettings["configValue"]));
For simple log messages, the saving may be minimal, but if the log involves walking the current stack to retrieve parameter values, it may be worth having. The sample above writes the current time and a configuration value to the log, if set to Debug. With the log level set to Warn, the log isn't written. Executing the call 1,000,000 times at Warn level consistently takes over 3.7 seconds if the logger call is made directly, and less than 0.08 seconds if the Lambda delegate is used:
!(/images/eltonstoneman/making-logging-cheaper-with-lambda-expressions/25664200-041509_2207_MakingLoggi1.png)
With a Warn call, the log is active and the direct and Lambda variants run 5,000 calls in 8.6 seconds, writing to a rolling log file appender:
!(/images/eltonstoneman/making-logging-cheaper-with-lambda-expressions/942099ea-041509_2207_MakingLoggi2.png)
I've added the logger and test code to the MSDN Code Gallery sample: Lambda log4net Sample, if you're interested in checking it out.