Log4Net versus Enterprise Library 2.0 Logging Application Block (Part I - File Logging)
With the release of the Enterprise Library 2.0 Application Blocks from Microsoft I was interested to find out if the Logging Application Block provided is faster than the tried and true Log4Net library I've been using for a few years from SourceForge. To do this, I figured I'd perform two sets of head-to-head tests - flat file based logging and database logging.
Part I - File logging
I first decided to tackle file based logging as it is easier to get set up and would allow me to get familiar with the basics of the new application block code. In order to make it a fair test I had to make sure the application block would be configured to log the same output I'm getting with my customzied Log4Net wrapper class. My standard output fields from Log4Net with every log entry are:
- DateTime stamp
- Tick count (in case logging occurs at the same millisecond the tick count is more finite and allows me to determine the order of events in tied time stamp records)
- Log Level (Error, Warning, Info, Debug, Verbose), some people call it severity
- Machine name
- Thread ID
- Source (the name of the assembly and class logging the message)
- Method (name of the method logging the message)
- Context (optional additional context data, not used in these tests)
- Message
The Logging application block code was able to give me all of the above fields except for the Source and Method. This didn't surprise me too much as I had to customize Log4Net to get that information originally. So, to make the tests equivalent I took the same reflection code that I use in my Log4Net wrapper class and put it in the test application to look up the source and method values and pass them in with the Logging Application Block Logger.Write method.
The one significant difference between the two loggers that could affect the results is that the code for Log4Net was written for the .Net 1.1 Framework and the Enterprise Library Logging Application Block was written for the .Net 2.0 Framework. Advantage: Logging Application Block.
The output for each log would be a single line entry in a text file. Here is the conversion pattern used for the Log4Net AllTypesRollingLogFileAppender in the app.config:
<!--
value="#TIME TICK_COUNT THREAD_ID LOG_LEVEL MACHINE_NAME SOURCE METHOD CONTEXT MESSAGE\r\n" --><param name="ConversionPattern" value="%d{yyyy'-'MM'-'dd HH':'mm':'ss'.'fff}|*|%P{tick_count}|*|%-5p|*|%X{machine}|*|%t|*|%c|*|%M|*|%x|*|%m|*|%n"/>
Here is the formatter for the Logging Application Block that the Flat File TraceListener will use. I'm adding two dictionary entries with a key name of Source and Method in my code so they will appear in the dictionary section of the output format string.
<
formatters>
<
add template="{timestamp}|*| {win32ThreadId}|*|{severity}|*|{machine}|*|{dictionary({key} - {value}; )}|*|{message}"
type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null" name="Text Formatter" />
</
formatters>
The (Unofficial) Results
After getting my test application together it would simply run a loop writing log entries based on a user entered loop iteration count. Both loggers would continue appending the entries to their respective log file until the test cycle was done. The next text cycle would start with a fresh log file again. I also ran an iteration of one log entry for each logger as an initializer as each logger has an initial performance hit when first called to initialize the file, load assemblies and spin up shared resources. The WinForm test application was run in stand-alone release mode to simulate a normal production application.
Test Run 1
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
140 |
190 |
| 1 |
20 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
50 |
40 |
| 1000 |
430 |
360 |
| 10000 |
3955 |
3545 |
Test Run 2
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
150 |
190 |
| 1 |
10 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
70 |
30 |
| 1000 |
400 |
350 |
| 10000 |
3915 |
3485 |
Test Run 3
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
140 |
190 |
| 1 |
20 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
50 |
40 |
| 1000 |
390 |
340 |
| 10000 |
3965 |
3545 |
So far the Logging Application Block is winning the competition. I'd be interested to know if there are changes that could be made to Log4Net to take advantage of the changes in the .Net Framework 2.0 and eliminate the time differences or if the Logging Application Block would still hold the advantage.
For my next segment I'll display the results of testing the two loggers writing to a SQL database. Stay tuned!