January 10, 2012 at 10:01Logging - silence performance
In the discussions of this article , I finally had a desire to evaluate the speed characteristics of the API loggers in numbers.
I decided to make a comparison of the delays when using the NLog and Log4Net loggers, as well as to highlight a few general questions on measuring the performance of code sections in .Net and Mono.
For the case when the log is on, performance is made up of the following components:
In NLog and Log4Net, all of these systems vary widely in both composition and architecture. In addition, they can be tuned differently in order to improve performance. Therefore, for the included log I could not formulate non-“holivarnyh” tests.
But, as already mentioned, a disabled logger should have a minimal effect on the speed of the application. Therefore, let's try to compare the performance of a disabled logger. In this case, only the transfer of parameters to the logging call itself and the determination of the current logging level are affected.
To begin with, I repent and admit that my hopes for optimization with jit compilation have not yet been realized. No performance acceleration from hypothetical inline inserts was found. But, who knows, maybe frameworks will learn later ...
The console application loops through the function in which the Debug message is displayed.
Taken 6 functions.
To increase accuracy, the measurements were grouped so that the group performed more than 100 ticks of the system timer. The total number of group measurements is 200,000 for each function.
For a preliminary assessment of the distribution of the obtained data, a histogram was constructed. The right 5% of the values were excluded as random delays due to the influence of the operating system. Thus, the table presents average scores for 95% of cases and deviations for them.
Measurements were carried out on .Net (Windows 7) and Mono 2.10.2 (OpenSUSE 11.3).
The “slowdown” column is the slowdown of Log4Net relative to NLog. It was calculated adjusted for the execution time of the function call (time Em_1).
Each subsequent run of the test can return results that go beyond the calculated confidence intervals, and within one run this interval is not violated. Therefore, the performance rating can only be used relative. And therefore, measurements for both logging systems are carried out in one run.
Distribution of execution time of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
I do not quote the distribution of NLog, because it’s just a very narrow outlier of 2-3 values and there is still no form of distribution on the graph.
Distribution of execution time of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Similarly, the distribution of NLog does not cite.
If interested, you can build the graphs yourself.
The source codes of the benchmarks are here . Binaries, test results, data for histograms and graphs are separately stored . There are also examples of building histograms for GnuPlot.
The measurements were carried out on different machines, so you should not compare the performance of Mono and .Net. If it is interesting to compare platform performance, then you can read more about this in this work .
From the tables it is clear that for a trivial call, we get a speed loss of Log4Net more than 8 times. For a more realistic application, you should look at an example of output with 3 parameters, i.e. 13 and 32 for DotNet and Mono respectively.
Log4Net has an oddly long log-level verification time. So much so that it doesn't make much sense to use pre-checks.
If Log4Net is used under Mono, then we can observe pretty bizarre distributions. Based on my experience, I can immediately say that these are the machinations of GC. Apparently, Mono does worse with massive boxing of function parameters, and Log4Net leads all parameters to the object type . Because of this, the execution time is not even more predictable - the absolute error exceeds the value itself.
In real life, most likely, you will not need such a detailed logging that the speed of calling a disabled log will affect the speed of the algorithm. It is difficult to imagine how the service will behave if you turn on such a log. Also, you should be aware that we are talking about tens of nanoseconds.
The payload of the logged section of code is usually three orders of magnitude greater than the log call (tens of microseconds), and I / O operations by another three orders of magnitude (tens of milliseconds). Thus, the criterion of speed, when choosing a logger, is not yet significant.
Have a good development!
I decided to make a comparison of the delays when using the NLog and Log4Net loggers, as well as to highlight a few general questions on measuring the performance of code sections in .Net and Mono.
For the case when the log is on, performance is made up of the following components:
- Message rendering. It is possible to cache some parameters and calculate others asynchronously.
- The system for distributing messages to target / appenders.
- Message flow saving system.
In NLog and Log4Net, all of these systems vary widely in both composition and architecture. In addition, they can be tuned differently in order to improve performance. Therefore, for the included log I could not formulate non-“holivarnyh” tests.
But, as already mentioned, a disabled logger should have a minimal effect on the speed of the application. Therefore, let's try to compare the performance of a disabled logger. In this case, only the transfer of parameters to the logging call itself and the determination of the current logging level are affected.
To begin with, I repent and admit that my hopes for optimization with jit compilation have not yet been realized. No performance acceleration from hypothetical inline inserts was found. But, who knows, maybe frameworks will learn later ...
Testing methodology
The console application loops through the function in which the Debug message is displayed.
Taken 6 functions.
- N0_1 - output of a constant string.
- N0_100 - output of a constant string from 100 different threads
- N1_1 - output of a formatted message with 1 parameter.
- N3_1 - output a formatted message with 3 parameters.
- P0_1 - output line with pre-check (the number of parameters does not matter)
- Em_1 - empty (for estimating the speed of measurement strapping)
To increase accuracy, the measurements were grouped so that the group performed more than 100 ticks of the system timer. The total number of group measurements is 200,000 for each function.
For a preliminary assessment of the distribution of the obtained data, a histogram was constructed. The right 5% of the values were excluded as random delays due to the influence of the operating system. Thus, the table presents average scores for 95% of cases and deviations for them.
Measurements were carried out on .Net (Windows 7) and Mono 2.10.2 (OpenSUSE 11.3).
The “slowdown” column is the slowdown of Log4Net relative to NLog. It was calculated adjusted for the execution time of the function call (time Em_1).
Each subsequent run of the test can return results that go beyond the calculated confidence intervals, and within one run this interval is not violated. Therefore, the performance rating 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 | average time (ns) | average 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) | 10 |
| N3_1 | 60.6 (-1.2 +8.8) | 7.93 (-0.04 +0.03) | thirteen |
| P0_1 | 27.7 (-0.3 +0.3) | 4.438 (-0.004 +0.031) | 26 |
| Em_1 | 3.51 (-0.12 +0.24) | --- | --- |
Distribution of execution time of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
I do not quote the distribution of NLog, because it’s just a very narrow outlier of 2-3 values and there is still no form of distribution on the graph.
Testing under Mono 2.10.2 (OpenSUSE 11.3)
| Log4net | Nlog | ||
| function | average time (ns) | average 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) | --- | --- |
Distribution of execution time of functions with Log4Net:
Here: blue - N0_1, purple - N0_100, green - N1_1, red - N3_1.
Similarly, the distribution of NLog does not cite.
If interested, you can build the graphs yourself.
The source codes of the benchmarks are here . Binaries, test results, data for histograms and graphs are separately stored . There are also examples of building histograms for GnuPlot.
Results Analysis
The measurements were carried out on different machines, so you should not compare the performance of Mono and .Net. If it is interesting to compare platform performance, then you can read more about this in this work .
From the tables it is clear that for a trivial call, we get a speed loss of Log4Net more than 8 times. For a more realistic application, you should look at an example of output with 3 parameters, i.e. 13 and 32 for DotNet and Mono respectively.
Log4Net has an oddly long log-level verification time. So much so that it doesn't make much sense to use pre-checks.
If Log4Net is used under Mono, then we can observe pretty bizarre distributions. Based on my experience, I can immediately say that these are the machinations of GC. Apparently, Mono does worse with massive boxing of function parameters, and Log4Net leads all parameters to the object type . Because of this, the execution time is not even more predictable - the absolute error exceeds the value itself.
Applicability
In real life, most likely, you will not need such a detailed logging that the speed of calling a disabled log will affect the speed of the algorithm. It is difficult to imagine how the service will behave if you turn on such a log. Also, you should be aware that we are talking about tens of nanoseconds.
The payload of the logged section of code is usually three orders of magnitude greater than the log call (tens of microseconds), and I / O operations by another three orders of magnitude (tens of milliseconds). Thus, the criterion of speed, when choosing a logger, is not yet significant.
Have a good development!