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.

Acessing 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 environement 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.