.Net Logging Performance Comparison

In this article I tried to analyse and explain performance of the most frequent calls from .Net logging frameworks. All experiments were provided with log4net and NLog libraries, at Windows 10 x64 Intel with M.2 SSD.

Long story short — just check table below. It can be used as proof of fast (or slow) behavior of code.

Raw results are available at GitHub. Source code is there too, however you need to install .Net 4.7.2 and Microsoft Visual Studio 2017 or newer.

NoOpLogging

First, let’s measure how much time library spends on the calls, which do not lead to IO operations. In the most cases (based on my experience) developers turn off Debug level in production. However, logger calls do remain, but they do nothing (except some checks).

First of all — results:

And source code:

Let’s understand, why these tests are important for us:

• I used experiences under the most popular libraries
• NLog and log4net have different function signatures for small arguments count (see below log4net and next — NLog).

• Theory: .Net CLR should do boxing for a call with value type, for example — for int. Also, new object in heap is not needed, because logs are turned off. However, NLog does not exhibit this behavior (because of generic function signature), so looks like it should work faster.
• Both libraries have the same signatures for calls with many arguments, therefore it is better to understand:

1. Is it faster to call functions with fewer argument counts? If yes: how much faster?
2. Are there any performance difference between log4net and NLog, if calling method ```Is…Enabled```.

Now let’s understand the results:

• NLog uses function generic arguments, so it works faster for a case, when real logging is not needed. So, if your application needs ```Debug``` level only in tests, then you can just replace library used, which will lead to performance boost (and user’s experience improvement).
• If logging is usually turned off, and you want to call logging with many arguments, then it is better to split this call to multiples. This simple refactoring improves speed of your code by multiple times.
• If you write with method and with object parameter, usually it is better to create another one, with a generic signature. Such small optimization leads to performance boost, as an example — see difference between Log4NetSingleReferenceParam and Log4NetSingleValueParam.

FileLogging

The most of .Net applications (by my observation) do file logging. Therefore, let’s compare its performance. For the first simple case let’s configure our loggers to write data into the files without any buffering, any additional tricky locks, etc.

Results:

And source code:

• log4net:

• NLog:

As you can see, the configuration is the same, however:

• NLog is much faster than log4net (difference is about 15%)
• Based on performance measurement, it is more effective to call log methods with a lower parameter count (to be honest: log method should be generic, like Debug<TArg1, TArg2, …, TArgN>(…), instead of Debug(string format, params object[] args)). However, it is important to remember, that more parameters lead to a bigger output line, therefore, only NLog vs log4net comparison is right (with the same parameter count).

NLog — different locking schemes

Source code:

Replacing XXXXX and YYYYY with all combinations available, get four table lines.

Results are fairly predictable:

• ConcurrentWrites option orders system to gain and release Mutex, which is not free. However, we see, that time spent on Mutex ownership is the same with a single line file write.
• File opening and closing also has a major performance impact. Cases with KeepFileOpen=true mean that for each logging event NLog opens file (e.g. creates file system handle), then it writes data to disk, flushes all bytes, then handle is returned to the operating system. Of course, Windows generates a lot of another hidden actions, related to handle.

Asynchronous logging and different file locking modes

NLog also can do all IO operations on another thread, that immediately frees current one. Moreover, it does a great job with this, with event order keep, with solid block flush (to avoid line cut), etc.

Results:

Synchronious and asynchronious modes comparison will be next, here I observed the last one only.

AsyncTargetWrapper source:

As you can see, wrapper configuration allows logger to keep a lot of logging lines in the memory. So, library collects huge buffer; all expensive actions (such as FileOpen) are rarely executed. However, this algorithm requires a lot of additional memory.

Therefore:

• If you use asynchronous output then it does not matter, what file locking configuration was selected. You can open and close files on each IO attempt. And time for this operation will be spread between a number of logging executions.
• All measurements are correct only in the case, where log lines buffers are filled more slowly than application extra actions. This is due to natural pauses between case execution.

Synchronous and asynchronous logging

Results:

• Despite fast M.2 SSD, multithreaded logging improve performance by the multiple times. If your application writes on the HDD or on the virtualized environment then difference will be much bigger.
• However, in spite of fast asynchronous code, skipped logging works much faster (although achievements are different depending of library selected).

Logger construction

Results:

What was tested:

Important notice: unfortunately, I failed to create reproducible benchmark which does not lead to an “Out Of Memory” issue, which in the same time creates different loggers (for the different types, different lines, etc.).

However, after logging library analyzing I found, that the most of expensive operations are executed to create logging key (e.g. logger name understanding, generic arguments cleanup, etc.) Moreover, to stabilize logger creation benchmark for log4net I have to execute 16 operations (e.g. return array of the 16 references on the same logger instance). If function returns nothing, then .Net optimizes execution (probably just omitting a lot of final pure calls), which leads to the incorrect results.

And let’s analyse results:

• String-based loggers produce much faster (NLog works better, however let’s don’t forget, that the most of loggers are created to do some non-free logging).
• log4net works much faster than NLog during the project initialization. By my understanding, the cause is in additional caching at the NLog side, which helps to speedup Debug, Info and the same function calls. It means that each ILogger knows exactly about itself: needs to call next methods or not (and this requires logger and configuration two-way communication). Because of this I received “Out of Memory” with most tests (e.g. if you want to use different string lines, etc).
• LogManager.GetCurrentClassLogger() works slower than LogManager.GetLogger(typeof(XXX)). This is quite predictable, even NLog maintainers don’t recommend calling first one inside loops.
• And the most important: the performance impact on the cold application is at start only, when fields like: private static readonly ILogger Log = LogManager.GetCurrentClassLogger() are initialized. They don’t affect system performance thereafter.

Summary:

How it is better to operate with the logging frameworks?

• The fastest logging option — avoid any logging. It is obvious, however each logging call steals user’s computer performance. Moreover, NLog supports conditional logging (to disable debug function calls for release code).
• For projects with a lot of logging calls without the real IO operations:

1. Select NLog. It is faster and generates less memory traffic (ideally — zero).
2. Use four arguments or less, to avoid calling functions like Debug(string format, params object[] args)

• If you plan to do file output — use NLog in asynchronous mode. It eats more memory (in comparison with blocking mode), however works faster.

1. By my measurements, log4net in blocking mode produces more objects in memory than NLog at the asynchronous mode. Reason is with special tuning inside the NLog, such as created arrays reusage, unnecessary ToString calls avoid, etc.

• ILogger creation operation is not resource free, so it is better to create it as static field. However, string-based loggers (for example — LogManager.GetLogger(“123”)) are cheaper, so you can create them for huge objects, such as “user operation execution context”.

And advises four your own code (based on the our measurements):

• If your method receives any input type (e.g. object) and does nothing (which is true for contracts and validation) the it is better to use generic-like signature, for example — Something<TArg>(TArg arg). You will get guaranteed performance boost for the value types.
• If your code has IO operations, which can be done in parallel with additional work — it is better to spend time and support parallel execution. And yes, this looks obvious, however, this current article is proof, that such behavior can gain additional performance boost to computers with slow disk subsystem.