Here's are some intentionally dubious micro-benchmarks showing how to get more
bang-for-the-buck out of DateTime.Now in a tight loop. The cached DateTime
implementations are about 40% faster than the typical DateTime.Now. Internally
log4net uses DateTime.Now when creating a new LoggingEvent. Perhaps it would
benefit some people to optimize the repeated calls to DateTime.Now if there are
a lot of log messages being generated in a short amount of time...maybe things
like NHibernate's DEBUG logging would benefit? I thought the
CachedSecondDateTime which caches the ticks for a full second would be even
faster but its on par with CachedTicksDateTime:
class Program
{
static void Main(string[] args)
{
runner(new FrameworkDateTime());
runner(new CachedTicksDateTime());
runner(new CachedSecondDateTime());
runner(new HardCodedDateTime(DateTime.Now));
Console.ReadLine();
}
private static void runner(IDateTime dateTime)
{
using (var ms = new MemoryStream())
using (var writer = new StreamWriter(ms))
{
Stopwatch stopwatch = Stopwatch.StartNew();
for (int i = 0; i < 1000000; i++)
{
writer.Write(dateTime.Now.Ticks);
}
stopwatch.Stop();
Console.WriteLine(dateTime + ": " + stopwatch.ElapsedMilliseconds);
}
}
public interface IDateTime
{
DateTime Now { get; }
}
public sealed class FrameworkDateTime : IDateTime
{
public DateTime Now
{
get { return DateTime.Now; }
}
}
public sealed class CachedTicksDateTime : IDateTime
{
private DateTime cachedDateTime;
private long cachedTicks = 0;
public DateTime Now
{
get
{
long environmentTickCount = Environment.TickCount;
if (environmentTickCount != cachedTicks)
{
cachedTicks = environmentTickCount;
cachedDateTime = DateTime.Now;
}
return cachedDateTime;
}
}
}
public sealed class CachedSecondDateTime : IDateTime
{
private DateTime cachedDateTime;
private long cachedTicks = 0;
public DateTime Now
{
get
{
long environmentTickCount = Environment.TickCount;
if (environmentTickCount > cachedTicks)
{
cachedTicks = environmentTickCount +
TimeSpan.TicksPerSecond;
cachedDateTime = DateTime.Now;
}
return cachedDateTime;
}
}
}
public sealed class HardCodedDateTime : IDateTime
{
private readonly DateTime cachedDateTime;
public HardCodedDateTime(DateTime cachedDateTime)
{
this.cachedDateTime = cachedDateTime;
}
public DateTime Now
{
get { return cachedDateTime; }
}
}
}
NLog uses this clever trick to optmize calls to DateTime.Now. I'm pretty sure
log4net uses a similiar trick with the %date formatter.
----- Original Message ----
From: Ron Grabowski (JIRA) <j...@apache.org>
To: log4net-dev@logging.apache.org
Sent: Wednesday, February 4, 2009 5:39:59 PM
Subject: [jira] Commented: (LOG4NET-195) Log4Net Performance comparison with
other logging utility
[
https://issues.apache.org/jira/browse/LOG4NET-195?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12670533#action_12670533
]
Ron Grabowski commented on LOG4NET-195:
---------------------------------------
Wow, that's some interesting code. Let me see if I can summarize what you did:
You used this pattern string for log4net: "%-5p %d %5rms %-22.22c{1} %-18.18M -
%m%n". You used this pattern for nspring: "{date} {time} [{ln:uc}] {category}
{msg}\n". It looks like the log4net pattern string is doing quite a lot more in
terms of formatting don't you think?
You used a new StringBuilder to build the log4net message each time in the
tight loop but you used just one string StringBuilder in the nspring example.
Would you agree that its quite a bit more expense to make a new StringBuilder
each time within a loop rather than building the StringBuilder just once?
It appears that nspring uses background threads to write message to the file.
Log4net does the writing on the same thread by default. I suspect the large
time differences you're seeing is due to the fact that nspring is returning
after it has started the log process...not after all the log entries have
actually been written to the file.
You're trying to compare two unrelated things.
> Log4Net Performance comparison with other logging utility
> ---------------------------------------------------------
>
> Key: LOG4NET-195
> URL: https://issues.apache.org/jira/browse/LOG4NET-195
> Project: Log4net
> Issue Type: Test
> Affects Versions: 1.2.10
> Environment: .Net Framework 2.0, VS 2005, Windows XP
> Reporter: Ashish Khandelwal
> Priority: Critical
> Attachments: Log4Net_Vs_nSpring.zip
>
>
> I developed one utility to compare the performance between Log4Net and
> nSpring(another logging utility). The result I saw is surprise to me -
> Log4Net took more time than nSpring. It is surprise because "Log4net claims
> to be fast and flexible: speed first, flexibility second."
> Log4Net says:
> (http://logging.apache.org/log4net/release/manual/internals.html)
> One of the often-cited arguments against logging is its computational cost.
> This is a legitimate concern as even moderately sized applications can
> generate thousands of log requests. Much effort was spent measuring and
> tweaking logging performance. Log4net claims to be fast and flexible: speed
> first, flexibility second.
> Although test is saying Log4Net takes more time, I am still not convinced
> with the result achieved, considering the fact; Log4Net is widely accepted by
> the industry and known for its speed, reliability and flexibility.
> I would like to know why Log4Net is taking more time, we might be missing any
> setting or other which can boost the performance. Can you please help to know
> the reason?
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
