Marko Apfel - Afghanistan/Belgium/Germany

Management, Architecture, Programming, QA, Coach, GIS, EAI

  Home  |   Contact  |   Syndication    |   Login
  187 Posts | 2 Stories | 201 Comments | 4 Trackbacks

News



Twitter | LinkedIn | Xing

Archives

Post Categories

BizTalk

C#

Enterprise Library

SAP

SQL Server

Technologie

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.

posted on Tuesday, August 2, 2011 10:49 AM