In this article, I put the benchmarks of the most private calls to the loggers. I conducted all experiments on log4net and NLog, on Windows 10 x64 Intel with M.2 SSD.

To not read for a long time, the results table is immediately on top.

Raw results can be viewed on github . In the same repository code (to run, you need .Net 4.7.2 + Microsoft Visual Studio 2017+).

What, how and why - under the cut.

NoOpLogging

First, we estimate how much time we spend on calling the logging method, which ultimately leads to nothing. In most cases (in my experience) the verbose Debug is disabled on the combat servers, but no one removes calls.

First result:

And the code:

void Log4NetNoParams() => _log4Net.Debug("test"); void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument); void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument); void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void Log4NetMultipleValuesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); void NLogNetNoParams() => _nlog.Debug("test"); void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument); void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument); void NLogNetMultipleReferencesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void NLogNetMultipleValuesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); 

First, let's decide why these tests were chosen:

• Experiments were performed on the most popular libraries.

• NLog and log4net have different function signatures for a small number of arguments:

  
  
  • log4net:
  
  

   void DebugFormat(string format, object arg0) 

  
  
  • Nlog:
  
  

   void Debug(string message, string argument) void Debug<TArgument>(string message, TArgument argument) 

  
  
  • Theory: when transferring a meaningful type to log4net, boxing should occur, which simply spends processor time and leads to nothing. In the case of NLog - this behavior is absent, because the latter should work faster.
  
  
• The signatures for a large number of arguments in libraries are about the same, so I would like to know:
  
  • How much more effective to call methods with a small number of parameters.
  • Is there a difference in the speed of calling the "Is ... Enabled" method between the two libraries?

And now the analysis of the results:

• Due to the use of generic arguments in NLog, it works faster for the case when direct logging is not needed. That is, for the case when in your Debug program the level is enabled only on the test system, simply changing the library can speed up the work of the software (and improve the lives of users).
• If you have logging turned off, and you want to call a method with a large number of arguments, it is more efficient to split it into two. Due to this, calls to the methods above will work ten times faster.
• When you write a function that can take any object, it is often most effective to get confused and make a generic function. Due to such a simple optimization, the code will work faster (this is clearly seen on the time difference of calls to Log4NetSingleReferenceParam and Log4NetSingleValueParam )

Filelogging

Most programs (according to my observations) still log the results to a file, so for comparison we will select this operation. For simplicity, let's just take logger configurations when writing to a file without buffering, without additional locks, etc.

Results:

Code used:

• log4net:

 var roller = new RollingFileAppender(); roller.ImmediateFlush = true; roller.RollingStyle = RollingFileAppender.RollingMode.Once; roller.MaxFileSize = 128 * 1000 * 1000; 

• Nlog:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = false, KeepFileOpen = false }; 

As you can see, the configuration of the loggers is more or less similar, but according to the results:

• NLog is slightly faster than log4net, about 15%.
• According to the tests, it turned out that it is more efficient to log a smaller number of parameters. However, we must not forget that with a larger number of parameters, the resulting string also expanded. Therefore, in the table it is only correct to compare NLog versus log4net.

NLog - different locking methods

Source:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = XXXXX, KeepFileOpen = YYYYY }; 

If in place of XXXXX and YYYYY to put all possible combinations, we get a test from the table.

The results are pretty predictable:

• If you allow ConcurrentWrites, the system will constantly start to take and give to Mutex, which is not free. But, as we see, writing one line to a file is approximately equivalent to one system lock.
• Closing and opening a file, as we see, affects the system performance even more. In the examples with KeepFileOpen=true , we created a file for each logging operation (along with Handle), made a record on the disk, called Flush, gave it to Handle, and also made a lot of engine operations. As a result, the speed drops hundreds of times.

Asynchronous logging and various locking methods

The NLog library is also able to perform all IO operations on another thread, immediately freeing the current one. Moreover, it does this competently, preserving the order of events, dropping all the data in blocks, and in each block an integer number of events (so as not to get truncated strings), and so on.

The results of different ways of non-blocking work:

Comparison of blocking and asynchronous approaches will be further, and here - only the latter.

AsyncTargetWrapper code:

 new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync) { OverflowAction = AsyncTargetWrapperOverflowAction.Block, BatchSize = 4096, FullBatchSizeWriteLimit = 128 } 

As you can see, the settings of the wrapper are such that a direct reset to the file does not take a long time. Thus, a large buffer is accumulated, which means all resource-intensive operations like “open file” are performed once for the whole block. However, this algorithm requires additional memory (and quite a lot).

Findings:

• If asynchronous output is used, then it doesn’t matter what file options are used. You can open and close a file each time, with a large buffer it will be almost imperceptible.
• All measurements are true only for the case when the data is flushed to disk at about the same speed as the buffer filling (I did this at the expense of a fast file system + natural pauses between measurements).

Synchronous and asynchronous logging

Findings:

• Despite the fast disk (in my case - M.2 SSD), writing to a file in another thread speeds up the work several times. If your application writes to HDD drives, and even running on a virtual machine, the gain will be even greater.
• However, despite the even fast operation of the asynchronous code, the lack of logging gives an even greater gain (albeit a bit different, depending on the library).

Creating loggers

What tested:

 [Benchmark] public object CreateLog4NetFromString() { return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000)); } [Benchmark] public object CreateNLogFromString() { return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000)); } [Benchmark] public object CreateLog4NetLogger() { return new [] { LogManager.GetLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogTypeOfLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogDynamicLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(), // x16 times }; } 

An important remark: unfortunately, it was difficult for me to make a reproducible benchmark that does not lead to Out Of Memory, but that would create different loggers (i.e., for different types, for different lines, and so on).

However, having studied the work of the libraries, I found that perhaps the most ponderous operations are performed to create the logger key (i.e., name definition, clearing of Generic arguments, and so on).
Moreover, in order to stabilize the benchmark for creating a logger for log4net, I had to perform not one operation, but 16 (that is, an array of 16 identical objects is returned). If you do not return anything, then .Net for me optimized execution (apparently, just not returning the result), which led to incorrect results.

And the conclusions:

• Loggers are created from strings most quickly (NLog is again faster, but the difference between libraries is small, considering that loggers are created not just for that, but for subsequent work with them).
• log4net is faster than NLog when initializing a project. Perhaps it’s about additional caching on the NLog side, which helps to speed up calls to Debug , Info , etc. directly. In fact, each ILogger knows the answer for itself: whether the following methods should be called or not (and this requires at least some sort of binding to the general configuration). Because of this scheme of work, I went out of memory on most tests (if you use different lines, etc.).
• LogManager.GetCurrentClassLogger() is even slower than LogManager.GetLogget(typeof(XXX)) . This is logical, even NLog developers do not recommend calling the first method in a loop.
• And most importantly: the speed of all these methods often affects only the cold start of the application, when fields of the form private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . That is, it does not affect the performance of the system itself.

Conclusion

How best to handle logs:

• If it is possible not to log at all, this will be the fastest (which is obvious so far).
• If there are many logger calls in the project that do not reset the data to a file (to the console, etc.), then NLog is faster. In addition, it allocates fewer objects in the heap.
• If you still need to write to the file, then NLog works as fast as possible in asynchronous mode. Yes, he eats more memory (compared to NLog in the synchronous mode, as according to my previous measurements, log4net does not even try to reuse arrays and Stream 's). However, the program can work faster.
• Creating a logger is not a free operation, so it is often better to create it with a static field. This does not apply to the creation of a string, that is, something like LogManager.GetLogger("123") . Such calls work faster, which means that the logger can be created for large instances of objects (for example, "one logger for the context of the query execution").
• If you want to output a lot of parameters to the log, however, in most cases, there will not be a direct reset of the data to the file, then it is best to make several calls. Thus, NLog will not create additional objects on the heap if they are not needed there.

Conclusions for your code:

• If your method accepts an arbitrary object (ie, object ) and in most cases does nothing (which is true for contracts / validators), then it is more correct to wrap the calls in a generic form (that is, to make methods of the form Something<TArg>(TArg arg) ). This will really work faster.
• If in your code we allow a data reset of the file and work with something else in parallel, it is better to be confused and support this. Yes, it seems obvious that parallel execution can speed up work, however, in the case of IO operations, this approach also gives an additional performance boost on machines with slow disks.