Logging - silence performance
In the discussions of this article , I finally had a desire to evaluate in figures the speed characteristics of the API loggers.
I decided to compare the delays when using the NLog and Log4Net loggers, and also to highlight a few general questions on measuring the performance of code sections in .Net and Mono.
')
For the case when the log is enabled, the performance consists of the following components:
In NLog and Log4Net, all these systems vary greatly in composition and architecture. In addition, they can be configured in different ways to improve performance. Therefore, for the included log, I could not formulate no "holivarny" tests.
But, as already mentioned, a disabled logger should have a minimal effect on the speed of the application. Therefore, we will try to compare the performance of the disabled logger. In this case, only the transfer of parameters to the call logging itself and the determination of the current logging level are affected.
To begin with, I repent and admit that my hopes for optimizing with jit compilation have not yet come true. Acceleration of performance from hypothetical inline-inserts is not detected. But who knows, maybe later the frameworks will learn ...
The console application calculates in a loop the function in which the Debug message is displayed.
6 functions are taken.
To increase accuracy, the measurements were grouped in such a way that the group performed more than 100 ticks of the system timer. The total number of measurements of groups - 200,000 for each function.
For a preliminary assessment of the distribution of the data obtained, a histogram was constructed. The right 5% of the values ​​were excluded, as random delays caused by the influence of the operating system. Thus, the table presents the average estimates for 95% of cases and deviations for them.
Measurements were conducted on .Net (Windows 7) and Mono 2.10.2 (OpenSUSE 11.3).
The “slowdown” column is the Log4Net slowdown relative to NLog. Calculated with the amendment to the time of the function call (time Em_1).
Each subsequent test run may return results out of the calculated confidence intervals, and within one run this interval is not violated. Therefore, the performance assessment can only be used relative. And therefore, measurements for both logging systems are carried out in one run.
Time distribution of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Distribution NLog I do not cite, because it's just a very narrow ejection by 2-3 values ​​and the form of distribution on the graph is still there.
Time distribution of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Similarly, the distribution of NLog does not provide.
If interested, then you can build your own graphics.
Benchmark source codes are here . Separately stored binaries, test results, data for histograms and graphics. There are also examples of the construction of histograms for GnuPlot.
The measurements were performed on different machines, so you should not compare the performance of Mono and .Net. If it is interesting to compare the performance of platforms, then this can be read in more detail in this work .
From the tables it is clear that for a trivial call, we will get a speed degradation from Log4Net more than 8 times. For a more realistic application, you should look at the output example with 3 parameters, i.e. 13 and 32 for DotNet and Mono respectively.
Log4Net has a weirdly large time checking the logging level. So much so that it does not make much sense to use a pretest.
If Log4Net is used under Mono, then we can observe quite bizarre distributions. Based on my experience, I can immediately say that these are the machinations of GC. Apparently, Mono is worse at coping with massive boxing of function parameters, and Log4Net all parameters result in the object type. Because of this, the execution time is even more unpredictable - the absolute error exceeds the value itself.
In real life, most likely, such detailed logging will not be needed, that the speed of calling the disabled log will affect the speed of the algorithm. It is difficult to imagine how the service will behave, if such a log is included. Also, it should be aware that we are talking about dozens of nanoseconds.
The payload of the logged portion of the code is usually three orders of magnitude larger than the log call (tens of microseconds), and the operations associated with input / output by another three orders of magnitude (tens of milliseconds). Thus, the criterion of speed, when choosing a logger, is not yet significant.
Successful development!
I decided to compare the delays when using the NLog and Log4Net loggers, and also to highlight a few general questions on measuring the performance of code sections in .Net and Mono.
')
For the case when the log is enabled, the performance consists of the following components:
- Rendering message. It is possible to cache some parameters and calculate others asynchronously.
- The message distribution system by target / appender.
- System save messages.
In NLog and Log4Net, all these systems vary greatly in composition and architecture. In addition, they can be configured in different ways to improve performance. Therefore, for the included log, I could not formulate no "holivarny" tests.
But, as already mentioned, a disabled logger should have a minimal effect on the speed of the application. Therefore, we will try to compare the performance of the disabled logger. In this case, only the transfer of parameters to the call logging itself and the determination of the current logging level are affected.
To begin with, I repent and admit that my hopes for optimizing with jit compilation have not yet come true. Acceleration of performance from hypothetical inline-inserts is not detected. But who knows, maybe later the frameworks will learn ...
Testing method
The console application calculates in a loop the function in which the Debug message is displayed.
6 functions are taken.
- N0_1 - output a constant string.
- N0_100 - output a constant string from 100 different threads
- N1_1 - output formatted message with 1 parameter.
- N3_1 - output a formatted message with 3 parameters.
- P0_1 - output line with prechecking (the number of parameters does not matter)
- Em_1 - empty (to estimate the measurement measurement speed)
To increase accuracy, the measurements were grouped in such a way that the group performed more than 100 ticks of the system timer. The total number of measurements of groups - 200,000 for each function.
For a preliminary assessment of the distribution of the data obtained, a histogram was constructed. The right 5% of the values ​​were excluded, as random delays caused by the influence of the operating system. Thus, the table presents the average estimates for 95% of cases and deviations for them.
Measurements were conducted on .Net (Windows 7) and Mono 2.10.2 (OpenSUSE 11.3).
The “slowdown” column is the Log4Net slowdown relative to NLog. Calculated with the amendment to the time of the function call (time Em_1).
Each subsequent test run may return results out of the calculated confidence intervals, and within one run this interval is not violated. Therefore, the performance assessment can only be used relative. And therefore, measurements for both logging systems are carried out in one run.
Measurement results
Testing under .Net (Windows 7)
| Log4Net | Nlog | ||
| function | mean time (ns) | mean time (ns) | slowdown |
| N0_1 | 31.4 (-0.3 +0.4) | 6.83 (-0.05 + 0.02) | 8.4 |
| N0_100 | 31.9 (-0.8 +3.8) | 6.83 (-0.06 + 0.01) | 8.5 |
| N1_1 | 40.4 (-1.3 +2.9) | 7.25 (-0.13 +0.01) | ten |
| N3_1 | 60.6 (-1.2 +8.8) | 7.93 (-0.04 +0.03) | 13 |
| P0_1 | 27.7 (-0.3 +0.3) | 4,438 (-0,004 +0,031) | 26 |
| Em_1 | 3.51 (-0.12 +0.24) | --- | --- |
Time distribution of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Distribution NLog I do not cite, because it's just a very narrow ejection by 2-3 values ​​and the form of distribution on the graph is still there.
Testing under Mono 2.10.2 (OpenSUSE 11.3)
| Log4Net | Nlog | ||
| function | mean time (ns) | mean time (ns) | slowdown |
| N0_1 | 80.0 (-36.5 +5.5) | 6.924 (-0.004 +0.016) | 21 |
| N0_100 | 78.0 (-34.6 +11.3) | 6.924 (-0.004 +0.016) | 21 |
| N1_1 | 92.4 (-34.9 +13.3) | 6.926 (-0.006 +0.054) | 24 |
| N3_1 | 141 (-52 +848) | 7.635 (-0.015 +0.005) | 32 |
| P0_1 | 69.6 (-30.2 +4.8) | 4.351 (-0.011 +0.009) | 62 |
| Em_1 | 3.285 (-0.005 +0.005) | --- | --- |
Time distribution of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Similarly, the distribution of NLog does not provide.
If interested, then you can build your own graphics.
Benchmark source codes are here . Separately stored binaries, test results, data for histograms and graphics. There are also examples of the construction of histograms for GnuPlot.
Results analysis
The measurements were performed on different machines, so you should not compare the performance of Mono and .Net. If it is interesting to compare the performance of platforms, then this can be read in more detail in this work .
From the tables it is clear that for a trivial call, we will get a speed degradation from Log4Net more than 8 times. For a more realistic application, you should look at the output example with 3 parameters, i.e. 13 and 32 for DotNet and Mono respectively.
Log4Net has a weirdly large time checking the logging level. So much so that it does not make much sense to use a pretest.
If Log4Net is used under Mono, then we can observe quite bizarre distributions. Based on my experience, I can immediately say that these are the machinations of GC. Apparently, Mono is worse at coping with massive boxing of function parameters, and Log4Net all parameters result in the object type. Because of this, the execution time is even more unpredictable - the absolute error exceeds the value itself.
Applicability
In real life, most likely, such detailed logging will not be needed, that the speed of calling the disabled log will affect the speed of the algorithm. It is difficult to imagine how the service will behave, if such a log is included. Also, it should be aware that we are talking about dozens of nanoseconds.
The payload of the logged portion of the code is usually three orders of magnitude larger than the log call (tens of microseconds), and the operations associated with input / output by another three orders of magnitude (tens of milliseconds). Thus, the criterion of speed, when choosing a logger, is not yet significant.
Successful development!
Source: https://habr.com/ru/post/135454/
All Articles