logging-log4net-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ron Grabowski <rongrabow...@yahoo.com>
Subject Re: [jira] Commented: (LOG4NET-195) Log4Net Performance comparison with other logging utility
Date Wed, 04 Feb 2009 23:36:05 GMT
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) <jira@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.

Mime
View raw message