Avoid expensive ToString() calls in log4net
“premature optimization is the root of all evil.” (Donald Knuth)
And, if I might add: “ugly optimization is not so great either”.
We have some classes with rather expensive ToString() methods in our code base. When used in logs (specifically, log4net), we incured the performance penality even when the logging level (Debug/Info/Warn/…) was too low, and the log wasn’t even printed. In other words, ToString() was called before the log method, in order to build the single string that is the input parameter to Logger.Log().
Our ugly optimization was to add checks before every log line, as in:
if (logger.IsDebugEnabled) logger.Debug("Calling " + someObjectWithExpensiveToString); |
A better solution, which I just tested to work, is to use the …Format() family of methods. This way, you pass objects and not strings, which are then only converted to strings if there is a need.
logger.DebugFormat("Calling {0}", someObjectWithExpensiveToString); |
The following test assures me it actually works:
ILog logger = LogManager.GetLogger("Foo"); ToStringCounter counter = new ToStringCounter(); Assert.AreEqual(0, counter.ToStrings); Assert.IsFalse(logger.IsDebugEnabled); logger.DebugFormat("Expecting zero ToString() calls: {0}", counter); Assert.AreEqual(0, counter.ToStrings); |
Where ToStringCounter is simply a class that counts the number of calls to its ToString() method.
