Evaluation and Comparison of different logging Systems

Based on mantis ID 62 this article contains a report of a comparison of three different logging systems in order to prepare a relevant development decision. The three different systems are:

1. The openpetra internal logging system called TLogging
2. The Log4Net system from Apache
3. The nLog system

In the very first step only the documentation is referred because this has led to a preliminary decision against nLog. In the next step some log4net benchmarks has been done in order to get some experience with log4net.

Comparison of nlog and log4net

First Impression

Both systems ([Apache log4net] and [nLog]) are something similar. Both systems provide an Interface to [Chainsaw] and both systems provide a message system to a remote instance. Both systems handle the log-levels DEBUG, INFO, WARN, ERROR and FATAL and both systems can handle an output to a file or a set of files, to a database or to a xml-report or else and simultaneously.

Furthermore both systems can be configured by external xml-files and programmatically. And of course both systems can be used by mono. In Mono we cannot use the log4net.Appender.ColoredConsoleAppender but the log4net.Appender.ConsoleAppender (I think that is something we can live with), and it makes no sense to use the NetSendAppender and the OutputDebugStringAppender. The NetSendAppender writes logging events to the Windows Messenger service and this only can be used by using a .net framework and the OutputDebugStringAppender sends the message to a Debugger. This interface actually is used by Microsoft Software only.

The OutputDebugStringAppender may be an interesting option for troubleshooting. May be we can switch between frameworks ...

NLog itself does not provide such an easy feature overview. Referring [this page] you can find different versions of nlog. If you open either the [Version for mono] and [for .net 4.0] you will see the problem. You have to study the documentation in detail to see what is going on and what is not going on.

The apache solution is not a standalone solution but [one of four logging services] for java, c++, c# and php and so experience on one of those frameworks will help to understand the others.

Referring to the [Apache-FAQ] there is a set of requirements for a logging system.

Base Requirements

Reliability

Reliability means that a system logs something before an action is performed. Typical solutions are the log files of a web server. If the process does not have the privilege to write something to a file an error message is shown and the site is not delivered to the client.

This means that an Exception has been thrown if the logging does not work. A troubleshooting log system mustn't fulfill such an requirement. It's not a good idea to troubleshoot your software and find a problem in your logging system only.

1. log4net is not reliable. it reclaims to be a "best-effort and fail-stop logging system"
2. nlog does not provide any information about it

Thread Safetyness

Both systems are thread safe.

Example for detailed differences: Remote-Syslog

I've not investigated all differences but only three and I've described it only for one example because the following differences are typical.

Apache knows two Remote-Classes, [the RemotingAppender] and the [RemoteSyslogAppender].

The first provides a communication to a client providing a [IRemoteLoggingSink-Interface] and the second a very common and convenient udp-Interface. The documentation is reduced down to the most important facts.

The nlog provides "Targets" and among a set of targets there exists a DatabaseTarget Class and a DatabaseParameterInfo Class. But the Database parameters itself are not a target. They are used to define a specific database target. So the hierarchical code structure is something strange.

First Decision between nLog and log4net

In this case the decision is relative simple. We'll take log4net.

Log4net benchmarks

The benchmark tests

Basic idea of this test is to get some ideas about the using of the system, and the relative performance to TLogging. The basic question is: Makes it sense to change or not?

The openpetra sources contains source tree (csharp\ICT\Testing) which handles different software tests. Inside of this tree. A class is added to csharp\ICT\Testing\Common\Logging.Benchmark.Test.cs. This test is not a unit test in a convenient way because no assert is really done. Instead of this the System.Diagnostics.Stoppwatch is used to measure the time which is necessary to log 10.000 lines one by another.

The base routine is:

stopwatch.Reset();
stopwatch.Start();
 // Do 10.000 Logs
stopwatch.Stop();
// Log the time in Milliseconds

The different tests are:

TLogging

for (int i=0; i<10000; i++)
  {
    TLogging.Log("Entry: " + i);
  }

Log4NetDirect

 for (int i=0; i<10000; i++)
   {
     log.Debug("Entry: " + i);
   }

LogOnLevelDependency

 for (int i=0; i<10000; i++)
   {
     if (log.IsDebugEnabled) log.Debug("Entry: " + i);
   }

UseConsole

 for (int i=0; i<10000; i++)
   {
     System.Console.WriteLine("Entry: " + i);
   }

First differences

TLogging only knows one Log-Level and you can use all or nothing. In log4net you have the log-commands log.Debug("...") log.Info("..."), log.Warn(..."), log.Error("..." ) and log.Fatal("..."). In our example debug is used and benchmarks are done by the levels DEBUG and INFO and so we can measure the non logging speed too. UseConsole and TLogging will define a reference level and Log4NetDirect is used for a direct measurement. If a log entry requires a complex string it may be a good idea to check if a string is required to log and so the LogOnLevelDependency test has been created.

We are testing the performance to write the data to the console. In this case the speed depends if the console is visible or not. 10.000 Log are 10.000 Screen updates and sometimes it is a new line, a scroll or a scroll bar update only. If you want to do your own tests, you shall make sure, that the conditions are always the same.

Used Files

The log4net-files which are part of the apache software are placed in csharp\ThirdParty\log4net. Furthermore the file csharp\ICT\Testing\Common\Logging.Benchmark.Test.cs contains the tests and the file Tests.Common.xml in the same directory contains the log4net configuration. The file csharp\ICT\Testing\_bin\Debug\Tests.Common.dll is generated by Sharpdevelop and can be loaded by NUnit to run the performance tests.

Log Results

The picture shows Nant and the four "Tests". The border of the two logs lies between TLogging and Log4NetDirect.

The first difference is the amount of information. The log file contains the date and time and also the time in milliseconds (2011-01-05 15:22:52,078) the name of the thread which is actually logging ([TestRunnerThread]), the log level (DEBUG) the namespace (Tests.Common.Logging_Benchmark_Test), a value named ndc (nested diagnostic contexts) - this value is actually "[(null)]" and the logging text (Entry: 0).

The ndc may be deprecated and so this is acutally not investigated. First we have to decide to use log4net or not. Then we can investigate this point (or not). The most important point at all is that there is something more information in the log and this file provide a better structure so that you can use chainsaw.

In this case the test has been started using a hidden "Text Output" Tab but you must not start all the tests at once. Run a test, take the time and run the next test. This makes shure, that NUnit is set to a comparable state. The result are the following times for UseConsole: 7.165 mS, 7.184 mS, 7.459 mS, 7.233 mS, 2.166 mS 3401 mS, 7.217 mS and 7.183 mS.

The main line is something like 7,2 seconds but there are some tests running very much faster. If the tests are started too closely the processor speed will increase and so the result cannot be used. So it may be a good idea to run only tests below 15 seconds.

So let us say:

1. UseConsole: 7,2 S
2. TLogging: 9876, 9991 and 9835 -> 10 S.
3. Console logging
   1. Log4NetDirect (logging): 7902, 8333, 8235 and 8374 -> 8,3 S.
   2. Log4NetDirect (not logging): ~ 50 ms.
   3. LogOnLevelDependency (logging): 7903, 8637, 8564, 8193, 8568 - > 8,6 S.
   4. LogOnLevelDependency (not logging): ~ 1 mS.
4. Console and file logging
   1. Log4NetDirect (logging): 8349, 8634 - > 8,6 S
   2. LogOnLevelDependency (logging): 8675, 8888 - > 8,9 S
5. Console and filtering of "Entry" which means "not logging"
   1. LogOnLevelDependency (logging but filtered): ~ 20 mS

Let us start to define the 7,2 S of UseConsole as a 100% reference. TLogging needs 140% but it logs to the console and a file. In the first part the log4net only writes to a console and it needs 115% using no "if" and 120% by using an if and if log4net writes to the console and a file, it will use 120% and 124%. In any case TLogging is the slowest logging system but the speed cannot be the only reason to change. It is more a not a reason not to change.

Processor Throttling

This hint has been added after running the test.

The most of the different windows versions provide a program named [powercfg.exe http://support.microsoft.com/kb/324347]. Best guess to find this program may be WINDOWS\system32. This program provides a parameter "processor-throttle-ac" which enables to force the processor to a defined speed. This program writes data to the registry. Be careful, one of the undo paths is a reinstallation.

See: Using Powercfg.exe in a logon script to configure power management settings

log4net advantages

So let us put together the advantages of log4net:

1. a slightly increase of logging speed
2. an external config file which can be changed in a runtime situation can handle a set of different logging targets, layouters and filter
3. nearly no time consuming if the system is not logging
4. avoids a complex string construction inside of the own software if the system is not logging

Following points are not investigated actually

1. log4net can log events too. No benchmark tests are done in this case.
2. log4net handles a filter which may filter out a messsage holding a special value ("Entry") or filter out everything else.

Actually the filter cannot be used for the namespace and it does not exists a namespace filter. But it may be a good idea to write such a filter. In this case someone can switch on and of the logging systems up to 5 different levels and in the complete range of a namespace.

On the other side if we do not join the dll's to one dll, we easily can handle the logging for each dll independently of the other dlls without the need to write a namespace filter.