Home .NET Fast logging

Fast logging

by admin

In this article, I have placed benchmarks of the most private logger calls. I did all the experiments on log4net and NLog, on Windows 10 x64 Intel with M.2 SSD.

Raw results can be viewed at GitHub In the same repository code (will need .Net 4.7.2 + Microsoft Visual Studio 2017+ to run).

What, how, and why – under the cat.

To avoid a long read, a table of results :

Method Mean Error StdDev
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1, 144.677 ns 26.3805 ns 77.7835 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=true 1, 106.691 ns 31.4041 ns 87.5421 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=true 4, 804.426 ns 110.3406 ns 103.2126 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=true 5, 303.602 ns 104.3022 ns 102.4387 ns
KeepFileOpen=true, ConcurrentWrites=false, Async=false 5, 642.301 ns 73.2291 ns 68.4986 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=false 11, 834.892 ns 82.7578 ns 77.4117 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=false 731, 250.539 ns 14, 612.0117 ns 27, 444.8998 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=false 730, 271.927 ns 11, 330.0172 ns 10, 598.1051 ns
CreateLog4NetFromString 1, 470.662 ns 19.9492 ns 18.6605 ns
CreateNLogFromString 228.774 ns 2.1315 ns 1.8895 ns
CreateLog4NetLogger 21, 046.294 ns 284.1171 ns 265.7633 ns
CreateNLogTypeOfLogger 164, 487.931 ns 3, 240.4372 ns 3, 031.1070 ns
CreateNLogDynamicLogger 134, 459.092 ns 1, 882.8663 ns 1, 761.2344 ns
FileLoggingLog4NetNoParams 8, 251.032 ns 109.3075 ns 102.2463 ns
FileLoggingLog4NetSingleReferenceParam 8, 260.452 ns 145.9028 ns 136.4776 ns
FileLoggingLog4NetSingleValueParam 8, 378.693 ns 121.3003 ns 113.4643 ns
FileLoggingLog4NetMultipleReferencesParam 9, 133.136 ns 89.7420 ns 79.5539 ns
FileLoggingLog4NetMultipleValuesParam 9, 393.989 ns 166.0347 ns 155.3089 ns
FileLoggingNLogNetNoParams 6, 061.837 ns 69.5666 ns 65.0726 ns
FileLoggingNLogNetSingleReferenceParam 6, 458.201 ns 94.5617 ns 88.4530 ns
FileLoggingNLogNetSingleValueParam 6, 460.859 ns 95.5435 ns 84.6969 ns
FileLoggingNLogNetMultipleReferencesParam 7, 236.886 ns 89.7334 ns 83.9367 ns
FileLoggingNLogNetMultipleValuesParam 7, 524.876 ns 82.8979 ns 77.5427 ns
NoOpLog4NetNoParams 12.684 ns 0.0795 ns 0.0743 ns
NoOpLog4NetSingleReferenceParam 10.506 ns 0.0571 ns 0.0506 ns
NoOpLog4NetSingleValueParam 12.608 ns 0.1012 ns 0.0946 ns
NoOpLog4NetMultipleReferencesParam 48.858 ns 0.3988 ns 0.3730 ns
NoOpLog4NetMultipleValuesParam 69.463 ns 0.9444 ns 0.8834 ns
NoOpNLogNetNoParams 2.073 ns 0.0253 ns 0.0225 ns
NoOpNLogNetSingleReferenceParam 2.625 ns 0.0364 ns 0.0340 ns
NoOpNLogNetSingleValueParam 2.281 ns 0.0222 ns 0.0208 ns
NoOpNLogNetMultipleReferencesParam 41.525 ns 0.4481 ns 0.4191 ns
NoOpNLogNetMultipleValuesParam 57.622 ns 0.5341 ns 0.4996 ns

NoOpLogging

First, let’s estimate how much time we waste calling a method for logging which will end up going nowhere. In most cases (in my experience) on combat servers, multiword Debug is disabled, but no one removes the calls.

First the result :

Method Mean Error StdDev
NoOpLog4NetNoParams 12.684 ns 0.0795 ns 0.0743 ns
NoOpLog4NetSingleReferenceParam 10.506 ns 0.0571 ns 0.0506 ns
NoOpLog4NetSingleValueParam 12.608 ns 0.1012 ns 0.0946 ns
NoOpLog4NetMultipleReferencesParam 48.858 ns 0.3988 ns 0.3730 ns
NoOpLog4NetMultipleValuesParam 69.463 ns 0.9444 ns 0.8834 ns
NoOpNLogNetNoParams 2.073 ns 0.0253 ns 0.0225 ns
NoOpNLogNetSingleReferenceParam 2.625 ns 0.0364 ns 0.0340 ns
NoOpNLogNetSingleValueParam 2.281 ns 0.0222 ns 0.0208 ns
NoOpNLogNetMultipleReferencesParam 41.525 ns 0.4481 ns 0.4191 ns
NoOpNLogNetMultipleValuesParam 57.622 ns 0.5341 ns 0.4996 ns

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 us determine why these tests were chosen :

  • Experiments were performed on the most popular libraries
  • NLog and log4net have different function signatures for 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 you pass a meaningful type to log4net, there should be boxing, which just wastes CPU time and leads to nothing. In the case of NLog, there is no such behavior, so the NLog should be faster.

  • The signatures for a large number of arguments in the libraries are about the same, so I would like to know :
    • How much more efficient it is to call methods with few parameters.
    • Is there any difference in the speed of calling the "Is…Enabled" method between the two libraries
    • And now the analysis of the results :

      • By using generic arguments in NLog, it works faster for cases where you don’t want to do any logging directly. So for the case where your program has Debug level only on the test system, just changing the library can speed up the software (and make life better for the users).
      • If you have logging turned off and you want to call a method with more arguments, it is more efficient to split it into two. This will make the method calls above work ten times faster.
      • When you’re writing a function that can take any object, it’s often most efficient to go to the trouble of making a generic function. This simple optimization will make the code work faster (you can see it in the call time difference Log4NetSingleReferenceParam and Log4NetSingleValueParam )

      FileLogging

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

      Results :

      Method Mean Error StdDev
      FileLoggingLog4NetNoParams 8, 251.032 ns 109.3075 ns 102.2463 ns
      FileLoggingLog4NetSingleReferenceParam 8, 260.452 ns 145.9028 ns 136.4776 ns
      FileLoggingLog4NetSingleValueParam 8, 378.693 ns 121.3003 ns 113.4643 ns
      FileLoggingLog4NetMultipleReferencesParam 9, 133.136 ns 89.7420 ns 79.5539 ns
      FileLoggingLog4NetMultipleValuesParam 9, 393.989 ns 166.0347 ns 155.3089 ns
      FileLoggingNLogNetNoParams 6, 061.837 ns 69.5666 ns 65.0726 ns
      FileLoggingNLogNetSingleReferenceParam 6, 458.201 ns 94.5617 ns 88.4530 ns
      FileLoggingNLogNetSingleValueParam 6, 460.859 ns 95.5435 ns 84.6969 ns
      FileLoggingNLogNetMultipleReferencesParam 7, 236.886 ns 89.7334 ns 83.9367 ns
      FileLoggingNLogNetMultipleValuesParam 7, 524.876 ns 82.8979 ns 77.5427 ns

      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, and according to the results :

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

      NLog- different ways of blocking

      Method Mean Error StdDev
      KeepFileOpen=true, ConcurrentWrites=false, Async=false 5, 642.301 ns 73.2291 ns 68.4986 ns
      KeepFileOpen=true, ConcurrentWrites=true, Async=false 11, 834.892 ns 82.7578 ns 77.4117 ns
      KeepFileOpen=false, ConcurrentWrites=false, Async=false 731, 250.539 ns 14, 612.0117 ns 27, 444.8998 ns
      KeepFileOpen=false, ConcurrentWrites=true, Async=false 730, 271.927 ns 11, 330.0172 ns 10, 598.1051 ns

      Source Code :

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

      If we replace XXXXX and YYYYY with all possible combinations, we get the test from the table.

      The results are pretty predictable :

      • If you enable ConcurrentWrites, the system will start to take and give back Mutex all the time, which is not free. But, as we can see, writing one line to a file is roughly equivalent to one system lock.
      • Closing and opening a file, as we can see, has an even greater effect on system performance. In the examples with KeepFileOpen=true for every logging operation we have a file created (together with Handle), written to disk, called Flush, Handle returned and a lot of underlying operations performed. As a result, the speed drops hundreds of times.

      Asynchronous logging and various ways of blocking

      The NLog library can perform all IO operations on another thread and release the current thread immediately. And it does it skillfully, saving order of events, dumping all data in blocks, each block having integer number of events (to avoid truncated strings) and so on.

      Results of different ways of non-blocking :

      Method Mean Error StdDev
      KeepFileOpen=true, ConcurrentWrites=false, Async=true 1, 144.677 ns 26.3805 ns 77.7835 ns
      KeepFileOpen=true, ConcurrentWrites=true, Async=true 1, 106.691 ns 31.4041 ns 87.5421 ns
      KeepFileOpen=false, ConcurrentWrites=false, Async=true 4, 804.426 ns 110.3406 ns 103.2126 ns
      KeepFileOpen=false, ConcurrentWrites=true, Async=true 5, 303.602 ns 104.3022 ns 102.4387 ns

      A comparison of the blocking and asynchronous approaches will follow, but here is just the latter.

      Code AsyncTargetWrapper :

      new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync){OverflowAction = AsyncTargetWrapperOverflowAction.Block, QueueLimit = 10000}

      As you can see, the wrapper settings are such that direct resetting to a file doesn’t happen for quite a long time. Thus a large buffer is accumulated, which means that all resource-intensive operations like "open file" are performed once for the whole block. However, this algorithm requires additional memory (and a lot of it).

      Conclusions :

      • If asynchronous output is used, it doesn’t matter what selections are used with the file. You can open and close the file every time, with a large buffer it will be almost invisible.
      • All measurements are true only for the case when the reset to disk occurs at about the same speed as the buffer fill (I got it due to the fast file system + natural pauses between measurements).

      Synchronous and asynchronous logging

      Results : Method Mean Error StdDev Median
      KeepFileOpen=true, ConcurrentWrites=false, Async=true 1, 835.730 ns 55.3980 ns 163.3422 ns 1, 791.901 ns
      FileLoggingLog4NetNoParams 7, 076.251 ns 41.5518 ns 38.8676 ns 7, 075.394 ns
      FileLoggingNLogNetNoParams 5, 438.306 ns 42.0170 ns 37.2470 ns 5, 427.805 ns
      NoOpLog4NetNoParams 11.063 ns 0.0141 ns 0.0125 ns 11.065 ns
      NoOpNLogNetNoParams 1.045 ns 0.0037 ns 0.0033 ns 1.045 ns

      Conclusions :

      • Despite the fast disk (in my case a M.2 SSD), writing to the file in a different thread speeds up the performance several times over. If your application writes to HDD disks, and is running in a virtual machine, the gain is even greater.
      • However, despite even fast asynchronous code, the lack of logging gives even more gain (though slightly different, depending on the library).

      Creation of loggers

      Results :

      Method Mean Error StdDev
      CreateLog4NetFromString 1, 470.662 ns 19.9492 ns 18.6605 ns
      CreateNLogFromString 228.774 ns 2.1315 ns 1.8895 ns
      CreateLog4NetLogger 21, 046.294 ns 284.1171 ns 265.7633 ns
      CreateNLogTypeOfLogger 164, 487.931 ns 3, 240.4372 ns 3, 031.1070 ns
      CreateNLogDynamicLogger 134, 459.092 ns 1, 882.8663 ns 1, 761.2344 ns

      What we tested :

      [Benchmark]public objectCreateLog4NetFromString(){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};}

      Important remark : unfortunately, I had trouble making a reproducible benchmark which does not result in Out Of Memory, but which would create different loggers (i.e. for different types, for different strings, and so on).

      However, after studying how the libraries work, I found that almost the heaviest operations are performed to create the logger key (i.e. name definition, clearing of Generic arguments, and so on).
      Moreover, to stabilize the benchmark for creating the logger for log4net, I had to perform not one operation, but 16 (i.e. an array of 16 identical objects is returned). If I didn’t return anything, the .Net optimized the execution for me (apparently just not returning the result), which led to incorrect results.

      And conclusions :

      • The fastest loggers are created from strings (NLog is faster again, but the difference between the libraries is small, considering that loggers are not created for nothing, but to work with them later).
      • log4net works faster than NLog when initializing a project. Perhaps it’s the extra caching on the NLog side, which helps speed up calls directly to Debug , Info etc. In fact, each ILogger knows the answer for itself: should the following methods be called or not (and this kind of thing requires at least some binding to the general configuration). Because of this working scheme, I had Out Of Memory on most tests (if using different strings, etc.).
      • LogManager.GetCurrentClassLogger() works even slower than LogManager.GetLogget(typeof(XXX)) This makes sense, even the NLog developers don’t 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 like private static readonly ILlogger Log = LogManager.GetCurrentClassLogger() That is, it doesn’t directly affect the performance of the system.

      Output

      What is the best way to handle logs :

      • If it is possible to not log at all, this would be the fastest (which is obvious so far).
      • If you have a lot of logger calls in your project that don’t dump data to a file (console, etc.), NLog is faster. Plus it allocates fewer objects in the pile.
      • If you do need to write to a file, NLog works fastest in asynchronous mode. Yes, it eats more memory (compared to NLog in synchronous mode, because according to my previous measurements, log4net doesn’t even try to reuse arrays and Stream ‘s). However, the program will be able to run faster.
      • Creating a logger is a non-paying operation, so it’s often better to create it with a static field. This does not apply to creating from a string, i.e. something like LogManager.GetLogger("123") Calls like this work faster, which means the logger can also be created for larger object instances (e.g., "one logger for a query execution context").
      • If you want to log a lot of parameters, but in most cases you won’t directly dump the data to a file, it’s best to make multiple calls. That way NLog won’t create additional objects in the heap if you don’t need them there.

      Conclusions for your code :

      • If your method accepts an arbitrary object (i.e. object ) and mostly does nothing (which is true for contracts/validators), it is more correct to wrap the calls in a generic form (i.e. make methods like Something<TArg> (TArg arg) ). This will work really fast.
      • If your code allows resetting a data file and working on something else in parallel, you’d better get weird and support something like that. Yes, it seems obvious that parallel execution can speed things up, but in the case of IO operations this approach also gives you an additional performance boost on machines with slow disks.

      You may also like