Performance-Analyzing of log4net regarding creation of new logger vs. taking an existing one

Motivation

During playing with AOP framework PostSharp I thought about the technique to weave the logger instances inside the code by using the CompileTimeInitialize–method. Unfortunately my logging-stuff must be serializable. This is not given. So I must use the other weaving point and access my Loggers.

Over an abstraction layer I use log4net in the background. So my question was: how expensive is access to loggers and log something.

Testing-Setup

My little testing project consists mostly of these lines:

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using NUnit.Framework;
using log4net;
using log4net.Config;

namespace EsriDE.Commons.Logging.log4net.Analyzing
{
    [TestFixture]
    public class Fixture
    {
        IEnumerable<Guid> _guids = GetGuids();

        [TestFixtureSetUp]
        public void TestFixtureSetUp()
        {
            var configFile = new FileInfo("log4net.config");
            XmlConfigurator.Configure(configFile);
        }

        [Test]
        public void testing_performance_of_a_bunch_of_individual_loggers()
        {
            var watch = Stopwatch.StartNew();
            foreach (var guid in _guids)
            {
                var s = guid.ToString();
                var log = LogManager.GetLogger(s);
                log.Debug(s);
            }
            watch.Stop();

            Debug.WriteLine("Ellapses time for individuals: " + watch.ElapsedMilliseconds);
        }

        [Test]
        public void testing_one_definied_logger_with_recalculating()
        {
            var s = new Guid().ToString();
            var watch = Stopwatch.StartNew();
            foreach (var guid in _guids)
            {
                var log = LogManager.GetLogger(s);
                log.Debug(s);
            }
            watch.Stop();

            Debug.WriteLine("Ellapses time for definied recalculated logger: " + watch.ElapsedMilliseconds);
        }

        [Test]
        public void testing_one_definied_logger_without_recalculating()
        {
            var s = new Guid().ToString();
            var log = LogManager.GetLogger(s);
            var watch = Stopwatch.StartNew();
            foreach (var guid in _guids)
            {
                log.Debug(s);
            }
            watch.Stop();

            Debug.WriteLine("Ellapses time for definied logger: " + watch.ElapsedMilliseconds);
        }

        private static IEnumerable<Guid> GetGuids()
        {
            for (int i = 0; i < 100000; i++)
            {
                var guid = Guid.NewGuid();
                yield return guid;
            }
        }
    }
}

with this log4net-configuration:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <configSections>
        <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
    </configSections>

    <log4net>
        <!-- Define some output appenders -->
        <appender name="RollingLogFileAppenderDebug" type="log4net.Appender.RollingFileAppender">
      <file value="${APPDATA}\ESRI Deutschland GmbH\EsriDE.Commons.Logging.log4net.Analyzing\Logs\DEBUG.log" />
            <appendToFile value="true" />
            <maxSizeRollBackups value="10" />
            <maximumFileSize value="500000" />
            <rollingStyle value="Size" />
            <staticLogFileName value="true" />
            <layout type="log4net.Layout.PatternLayout">
                <header value="------ [Log Header] ------&#13;&#10;" />
                <footer value="------ [Log Footer] ------&#13;&#10;" />
                <conversionPattern value="%date %-5level %logger - %message%newline" />
            </layout>
        </appender>

        <appender name="DebugAppender" type="log4net.Appender.DebugAppender">
            <layout type="log4net.Layout.PatternLayout">
                <conversionPattern value="%m%n" />
            </layout>
        </appender>

        <!-- Setup the root category, add the appenders and set the default level -->
        <root>
            <level value="DEBUG" />
            <appender-ref ref="RollingLogFileAppenderDebug" />
            <!--<appender-ref ref="DebugAppender" />-->
        </root>
    </log4net>
</configuration>

Result

with DbgView I could catch the output:

[8176] Ellapses time for definied recalculated logger: 1895 
[8176] Ellapses time for definied logger: 1023 
[8176] Ellapses time for individuals: 3117

Conclusion

What I have learned?

Accessing a new logger and logging is three times slower that log to a known logger.

Accessing a known logger and logging is in the middle of this span.

All three variants are in the same order of magnitude and in my environment with 100.000 logs in a few seconds insignificant.

So I could relinquish to the compile time initializing and use the method boundary stuff with recalculating the right logger.