You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-user@logging.apache.org by "mjones@imagehawk.com" <mj...@imagehawk.com> on 2006/07/23 15:12:45 UTC
Performance #'s for Log4Net and some ideas about how they can be
improved
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.
Re: Performance #'s for Log4Net and some ideas about how they can
be improved
Posted by Jaroslaw Kowalski <ja...@jkowalski.net>.
Ron Grabowski wrote:
> Jaroslaw Kowalski has written benchmarking code for NLog:
>
> http://svn.nlog-project.org/repos/nlog/trunk/NLog/tests/NLog.Benchmark/
hy don't you just cache the isXXXXEnabled flags and just return the
precalculated values in IsXXXEnabled? This would effectively turn most
non-logging tests into single boolean comparison as it is done in NLog.
It would probably require some mechanism to flush the cache, but should
be doable.
BTW. Here are my results of running NLog.Benchmark. The results are in
nanoseconds. I'll write some more explanation, and the reason for NLog
being so fast tomorrow.
<results>
<framework name="Log4Net">
<test name="Guarded no logging" min="41" max="42" avg="42" />
<test name="Unguarded no logging" min="46" max="47" avg="47" />
<test name="Unguarded no logging with formatting 1" min="92"
max="109" avg="100" />
<test name="Unguarded no logging with formatting 2" min="127"
max="130" avg="129" />
<test name="Unguarded no logging with formatting 3" min="132"
max="144" avg="139" />
<test name="Null target without rendering" min="1532" max="1592"
avg="1559" />
<test name="Null target without rendering 1" min="2264" max="2361"
avg="2321" />
<test name="Null target without rendering 3" min="2421" max="2478"
avg="2455" />
<test name="Null target with rendering" min="3142" max="3198"
avg="3174" />
<test name="Null target with rendering 1" min="3988" max="4157"
avg="4029" />
<test name="Null target with rendering 3" min="4182" max="4265"
avg="4226" />
<test name="Simple file" min="12968" max="14935" avg="13490" />
</framework>
<framework name="NLog">
<test name="Guarded no logging" min="3" max="3" avg="3" />
<test name="Unguarded no logging" min="6" max="6" avg="6" />
<test name="Unguarded no logging with formatting 1" min="8" max="9"
avg="8" />
<test name="Unguarded no logging with formatting 2" min="47"
max="49" avg="48" />
<test name="Unguarded no logging with formatting 3" min="49"
max="89" avg="57" />
<test name="Null target without rendering" min="185" max="215"
avg="201" />
<test name="Null target without rendering 1" min="342" max="432"
avg="386" />
<test name="Null target without rendering 3" min="565" max="663"
avg="602" />
<test name="Null target with rendering" min="2813" max="3001"
avg="2890" />
<test name="Null target with rendering 1" min="3140" max="3445"
avg="3229" />
<test name="Null target with rendering 3" min="3430" max="3648"
avg="3530" />
<test name="Simple file" min="4783" max="6356" avg="5231" />
</framework>
</results>
Jarek
Re: Performance #'s for Log4Net and some ideas about how they can be improved
Posted by Ron Grabowski <ro...@yahoo.com>.
Jaroslaw Kowalski has written benchmarking code for NLog:
http://svn.nlog-project.org/repos/nlog/trunk/NLog/tests/NLog.Benchmark/
that tests a variety of logging scenerios. The tests can be configured
to report on comparable NLog, log4net, and EntLib LAB configurations.
Have you run log4net through a code profiler? You may be surprised find
that code that looks slow is not the same code that is responsible for
poor performace. dotTrace and ANTS Profiler are two good tools:
http://www.jetbrains.com/profiler/
http://www.red-gate.com/products/ants_profiler/
I discovered that calls to ReaderWriterLock.AcquireReaderLock() were
more expensive than code I thought was going to be slow. As for the
for() loop in the Hierarchy repository...the class is by design a
hierarchly structure containing parents and childerns. At some point,
it needs to walk the tree to look for items. If the for() loop is only
executed two or three iterations I doubt there will be much improvement
by trying to refactor the loop into a non-loop.
Of course making things faster isn't just about fixing what the
profiler found to be slow. Are you able to create a diff against the
trunk using your modified class?
I'm very open to improving performance so long as it doesn't break (or
breaks as little as possible) existing code. The log4net-dev list is
probably a better place for discussions like this.
--- "mjones@imagehawk.com" <mj...@imagehawk.com> wrote:
> 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.
[snip]