logging-log4net-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ron Grabowski <rongrabow...@yahoo.com>
Subject Faster %date{yyyy-MM-dd hh:mm:ss tt} pattern converter
Date Sat, 12 Apr 2008 17:17:56 GMT
This is a faster pattern converter for the "yyyy-MM-dd hh:mm:ss tt" pattern. I use this primarily
with my NHibernate logger in DEBUG mode because I want to see what NHibernate is doing but
I don't necessarily care about timings down to the millisecond when its writing out its generated
sql and building objects. When I use this pattern converter my app doesn't feel slow when
NHibenrate DEBUG logging is enabled:

public class NoMillisecondsPatternConverter : PatternLayoutConverter
{
    private long nextSecond;
    private string cachedTimeStamp;

    protected override void Convert(TextWriter writer, LoggingEvent loggingEvent)
    {
        if (loggingEvent.TimeStamp.Ticks > nextSecond)
        {
            cachedTimeStamp = loggingEvent.TimeStamp.ToString("yyyy-MM-dd hh:mm:ss tt");
            nextSecond = loggingEvent.TimeStamp.Ticks + TimeSpan.TicksPerSecond; // ???
        }

        writer.Write(cachedTimeStamp);
    }
}

Here's a simplistic benchmark that compares the two:

class Program
{
    static void Main(string[] args)
    {
        runner(new SimpleDateFormatter("yyyy-MM-dd hh:mm:ss tt"));
        runner(new NoMillisecondsDateFormatter());
    }

    public static void runner(IDateFormatter dateFormatter)
    {
        StubTextWriter writer = new StubTextWriter();

        Console.Write(dateFormatter + ": ");
        Stopwatch stopwatch = new Stopwatch();
        stopwatch.Start();
        for (int i = 0; i < 10000000; i++)
        {
            dateFormatter.FormatDate(DateTime.Now, writer);
        }
        stopwatch.Stop();
        Console.WriteLine(stopwatch.ElapsedMilliseconds);
    }
}

 log4net.DateFormatter.SimpleDateFormatter: 17185
 ConsoleApplication1.NoMillisecondsDateFormatter: 3561

NoMillisecondsDateFormatter is about 80% faster by not showing the milliseconds.

This is how you use the code:

 <layout type="log4net.Layout.PatternLayout">
   <converter>
     <name value="date" />
     <type value="Company.Logging.NoMillisecondsPatternConverter, Company.Logging" />
   </converter>
   <conversionPattern value="%5level %date (%logger) - %message%newline" />
 </layout>

or you could create a custom pattern layout to more easily share the converter:

 <layout type="Company.Logging.MoMillisecondsPatternLayout">
   <conversionPattern value="%5level %date (%logger) - %message%newline" />
 </layout>

Log4net uses a similiar caching approach with the built-in date formatters: %date{DATE}, %date{ABSOLUTE},
etc. Those are much faster than using your own predefined layout because they cache most of
the slow changing components of the logging event's TimeStamp like year, month, day, hour,
minute, and second then only calculate the millisecond when generating the string.

This is interesting article about faster ways of formatting time by calculating the offsets
manually:

 Performance Quiz: Fastest way to format time
 http://geekswithblogs.net/akraus1/archive/2006/04/23/76146.aspx


Mime
View raw message