I've written some small sample code because I wanted to see how bad the
performance hit was between
if (log.IsDebugEnabled)
log.Debug(Message);
and
log.Debug(Message);
My thoughts on the issue were that the cleaner code is what I would like
to have in my projects even if there were a slight performance issue.
What I uncovered was that the performance was really bad in comparison
to what I could write when the code was NOT logging. I haven't looked
at performance when logging, concentrating my observations on the
majority of cases where the code remains in, but does NOT log anything.
What I found to me is a bit frightening even though it may not bother
you at all.
Here are the #'s that I found. They are in ticks (milliseconds) and are
based on 1 billion logging calls made that do nothing except decide NOT
to log
My code Non-optimized: 1402
My code optimized: 1392
log4net Non-optimized: 71593
log4net Optimized: 69089
Notice the fact that log4net is 49-51 times slower than my code when it
isn't logging. The configuration is being done in the assemblyInfo.cs
and the loglevel is being set with:
<root>
<level value="ERROR" />
<appender-ref ref="ColoredConsoleAppender" />
</root>
The C# code I used is below.
namespace SpeedTest {
class Program {
static void Main(string[] args) {
const int nIterations=1000000000;
{
logger log = new logger(int.Parse(args[0]));
String Message = "This is my message";
int nStart = Environment.TickCount;
for (int i = 0; i < nIterations; ++i) {
log.Debug(Message);
}
int nEnd = Environment.TickCount;
Console.WriteLine("My code Non-optimized: " + (nEnd -
nStart).ToString());
nStart = Environment.TickCount;
for (int i = 0; i < nIterations; ++i) {
if (log.IsDebugEnabled)
log.Debug(Message);
}
nEnd = Environment.TickCount;
Console.WriteLine("My code optimized: " + (nEnd -
nStart).ToString());
}
{
//log4net.Config.DOMConfigurator.Configure();
log4net.ILog log = log4net.LogManager.GetLogger("root");
Console.WriteLine("log4net");
String Message = "log4net Non-optimized";
int nStart = Environment.TickCount;
for (int i = 0; i < nIterations; ++i) {
log.Debug(Message);
}
int nEnd = Environment.TickCount;
Console.WriteLine("log4net Non-optimized: " + (nEnd -
nStart).ToString());
Message = "log4net Optimized";
nStart = Environment.TickCount;
for (int i = 0; i < nIterations; ++i) {
if (log.IsDebugEnabled)
log.Debug(Message);
}
nEnd = Environment.TickCount;
Console.WriteLine("log4net Optimized: " + (nEnd -
nStart).ToString());
}
}
}
}
What I notice when I debug the release build of the log4net stuff is this:
log.Debug(x)
becomes
Logger.Log(m_fullName, Level.DEBUG, message, t);
which becomes
if (Logger.IsEnabledFor(Level.DEBUG))
which becomes
virtual public ILogger Logger
{
get { return m_logger; }
}
which returns the logger
so that it can do
if (m_hierarchy.IsDisabled(level))
which becomes
if (((object)l) != null && ((object)r) != null)
{
return l.m_level == r.m_level;
}
else
{
return ((object)l) == ((object)r);
}
And then
if (Configured)
.......
Which leads to:
return level >= this.EffectiveLevel;
Which leads to:
for(Logger c = this; c != null; c = c.m_parent)
{
if (c.m_level != null)
{
return c.m_level;
}
}
return null; // If reached will cause an
NullPointerException.
We end up with function call after function call and a loop to figure
out a simple x > y question that we could have done by exploiting some
of the language features.
Now, what I'm thinking goes along the lines of making use of the
referential nature of c#. Creating a LogLevel class:
class MyLogLevel {
private int m_nLevel;
public int Level {
get {
return m_nLevel;
}
set {
m_nLevel = value;
}
}
public MyLogLevel(int nInitLevel) {
m_nLevel = nInitLevel;
}
}
Relying on the fact that every class that uses a logger uses a reference
to that logger, and that the log level itself can be a reference to
another variable we can do a little more work every time we process the
log properties file (and only then) to set the log level reference to
the correct one and to set the level within that reference to the
correct value. So if logger A,B,C, and D are not specified in the log
level, then they all reference the root logger. Then if the properties
file is modified, and A is referenced, but B,C, and D are not. The the
log level reference in A gets replaced (is not longer "root") with a new
log level instance that is set to the new value and B,C,D all keep their
reference to "root". This is extra overhead when the log properties is
loaded, but it is loaded far fewer times than Log.Debug is called.
I modified my logger code to do something like this (this is a test
class only, for proof of concept).
class logger {
private MyLogLevel m_nLogLevel;
private String m_strName;
public bool IsDebugEnabled {
get {
return m_nLogLevel.Level > 1;
}
}
public void Debug(object msg) {
if (m_nLogLevel.Level > 1) {
Console.WriteLine(m_strName + ": " + msg.ToString());
}
}
public logger(String strName, MyLogLevel nLevel) {
m_strName = strName;
m_nLogLevel = nLevel;
}
public MyLogLevel LogLevel {
get {
return m_nLogLevel;
}
set {
m_nLogLevel = value;
}
}
}
Sorry this was so long, but I wanted to throw it out for comment.
