So you have implemented a web site (with Episerver most likely if you are reading this blog ;P). Initial performance tests are done in the production environment and the site has gotten green to go live. The development didn’t stop to the ‘project’ but continues and new features are introduced. Depending on the case performance tests might be run for each release candidate or then not.
This post is not about how to do continuous development and all the best practices related to that. This post is a simple heads up about how logging might have a huge negative impact to your site performance.
I’ll use the Episerver MVC Alloy demo template to demonstrate how logging can have undesired effect to the web site performance. Alloy uses log4net for logging so if you Google for performance tuning then all those hits will apply (as long as the tip is actually correct).
Test machine (development machine)
- Intel Xeon E3-1231 v3 @ 3.40 GHz (turbo 3.80 GHz)
- (4 cores, 8 threads)
- 16 GB
Tools
- Apache JMeter 4.0
- with Java 9.x
- bombardier
Episerver CMS
- Episerver.CMS 11.3.3 (NuGet version)
- update 202
- all nuget.org NuGet updates applied (except json.net 11 as Epi is not yet compatible with it)
- log4net 2.0.8
- Alloy MVC site was created with the latest VS extension and without search
- running the site in release mode without debugging in the tests
Log4net default appender configuration
<appender name="infoLogAppender" type="log4net.Appender.RollingFileAppender" > <file value="App_Data\logs\InfoEpiLog4NetApp.log" /> <encoding value="utf-8" /> <staticLogFileName value="true"/> <datePattern value=".yyyyMMdd.'log'" /> <rollingStyle value="Date" /> <threshold value="Info" /> <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> <appendToFile value="true" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%date [%thread] %level %logger: %message%n" /> </layout> </appender> <logger name="EpiLog4Net.Controllers" additivity="false"> <level value="Info" /> <appender-ref ref="infoLogAppender" /> </logger>
Log info and above messages from controllers to a separate file (StartPageController is the only one having logging).
Reference performance
Initially I didn’t plan to use JMeter so I don’t have reference performance for it without any added log messages. Initially I just used bombardier to test the start page of Alloy.
Bombarding http://localhost:10506 with 10000 requests using 25 connections 10000 / 10000 [=========] 100.00% 24s Done! Statistics Avg Stdev Max Reqs/sec 491.69 790.98 15984.02 Latency 61.20ms 9.95ms 252.24ms HTTP codes: 1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0 others - 0 Throughput: 3.18MB/s
Adding log messages
To test how logging can affect the site performance I added two info level messages to StartPageController.cs index action. One to the start and another to inside the setting of edithints (it really doesn’t matter where in the code these log messages are as long as they are in the index action of the controller and no conditions when those are logged).
// log messages:
logger.Information("Start page index action called.");
logger.Information("Start page is the site real site start page, setting edit hints.");
So as you can see there is no expensive work done to create the actual log messages.
Performance with default log4net settings
Bombarding http://localhost:10506 with 10000 requests using 25 connections 10000 / 10000 [==============] 100.00% 3m15s Done! Statistics Avg Stdev Max Reqs/sec 51.08 13.82 210.47 Latency 488.87ms 120.16ms 1.42s HTTP codes: 1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0 others - 0 Throughput: 407.39KB/s
Erm, what did just happen to the stats?
- average request/s dropped from 491.69 to 51.08
- throughput dropped from 3.18MB/s to 407.39KB/s
- average latency dropped from 61.20ms to 488.87ms
Quick explanation: logging is synchronous, a write lock on the file is acquired per log message, log entry writen and lock released (See the remarks on FileAppender.MinimalLock). So under pressure the logging slows down the site performance because each message needs to wait for the write lock.
Use log4net ExclusiveLock
I modified the EPiServerLog.config (used to configure log4net) to use the ExclusiveLock (see the remarks).
// remove this line from infoLogAppender appender: <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
When that line is removed the default ExclusiveLock is used.
Performance with ExclusiveLock
Bombarding http://localhost:10506 with 10000 requests using 25 connections 10000 / 10000 [==================] 100.00% 24s Done! Statistics Avg Stdev Max Reqs/sec 538.13 721.72 9989.01 Latency 60.04ms 11.03ms 315.30ms HTTP codes: 1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0 others - 0 Throughput: 3.24MB/s
Yipee, back to the same ballpark in performance that we had before adding logging (yes, the performance looks even better than before but it is not something you should look at, single run was run and at the same time anything could have been done in Windows in the backgroud that was consuming resources).
So the question is that if there seems to be no performance penalty using ExclusiveLock then why isn’t it the default in Episerver log4net logging configuration? Well, because – there is no such thing as free lunch.
ExclusiveLock allows only one process to log to the file. The file is locked as long as the process exists that acquired the lock. So if you need to do something to the file from another process you can’t. I would ask why would you want to log from multiple processes to the same file – use centralized logging to collect the log files for example.
Another thing that doesn’t work with ExclusiveLock is IIS Web Garden feature by default unless you use unique log4net properties in constructing the file name so that is unique per IIS worker process. This same applies to Azure Web Apps – you need to make the log file names uniquer per instance (in case you are logging to your shared drive).
Use log4net BufferingForwardingAppender
What about using the combination of MinimalLocking and the log4net BufferingForwardingAppender?
Configuration
<appender name="infoLockingLogAppender" type="log4net.Appender.RollingFileAppender" > <file value="App_Data\logs\BufferedInfoEpiLog4NetApp.log" /> <encoding value="utf-8" /> <staticLogFileName value="true"/> <datePattern value=".yyyyMMdd.'log'" /> <rollingStyle value="Date" /> <threshold value="Info" /> <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> <appendToFile value="true" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%date [%thread] %level %logger: %message%n" /> </layout> </appender> <appender name="infoBufferingForwarder" type="log4net.Appender.BufferingForwardingAppender"> <bufferSize value="512" /> <lossy value="false" /> <Fix value="268" /> <!-- Flags: Message, ThreadName, Exception --> <appender-ref ref="infoLockingLogAppender" /> </appender> <logger name="EpiLog4Net.Controllers" additivity="false"> <level value="Info" /> <appender-ref ref="infoBufferingForwarder" /> </logger>
Performance with buffering
Bombarding http://localhost:10506 with 10000 requests using 25 connections 10000 / 10000 [===============] 100.00% 24s Done! Statistics Avg Stdev Max Reqs/sec 449.35 563.75 13988.81 Latency 61.93ms 8.77ms 240.23ms HTTP codes: 1xx - 0, 2xx - 10000, 3xx - 0, 4xx - 0, 5xx - 0 others - 0 Throughput: 3.14MB/s
So we are also in the same ballpark with performance with the BufferingForwardingAppender BUT…
If you look at the statistics you might notice there is a difference in the average requests per second: 538 vs 449, compared to the ExclusiveLock. My guess is that it relates to the fact that when the buffer hits its configured limit the log entries are writen to the underlying file and the log messages coming in needs to wait for this task to complete (its still asynchronous) but just a guess. The real but here is that you can easily loose log messages if the application is shutdown. In most cases this is not acceptable, so for this reason I wouldn’t use this approach.
Side note: in theory you should be able to react to the application shutdown (weather caused by recycle, stopped from IIS or app recycle because of crash) and call the log4net flush and shutdown methods, like this:
log4net.LogManager.Flush(10000); // wait 10 seconds log4net.LogManager.Shutdown();
Unfortunately I couldn’t get this to work. I kept loosing log entries. But then again as we should be using the Episerver logging abstraction this should be done by the logging implementation ;-P (it’s responsibility).
Conclusion
I would choose the ExclusiveLock option when there is need to log informative messages during normal execution, otherwise your site will be hit heavily with performance issues even with modest loads (see below JMeter results).
Its too easy to affect site performance with log4net by just using the default MinimalLock and then someone adds some informative logging to each page request, so now you know at least one way to workaround this.
Excersice for you is to find the proper actually working asynchronous file appender for log4net 😉 …and then let us all know about it (test it before you paste the first NuGet package hit).
And the JMeter results
So the bombardier tool is to hammer the site so I created a quick test plan for JMeter that loaded the start page with:
- 100 users
- ramp-up: 10 seconds
- loop count: 10
- 1000 request in total
- no cache or cookie manager, loading only the page HTML and no other resources
- used constant timer that added 1.5 seconds delay to each request (not hammering the site)
Default log4net configuration
- Average: 1673 ms
- Min: 53 ms
- Max: 2641 ms
- Throughput: 24.6 reqs/s
- Elapsed: 42 s
ExclusiveLock log4net configuration
- Average: 57 ms
- Min: 37 ms
- Max: 181 ms
- Throughput: 41.7 reqs/s
- Elapsed: 25 s
Buffering log4net configuration
- Average: 58 ms
- Min: 37 ms
- Max: 175 ms
- Throughput: 41.7 reqs/s
- Elapsed: 25 s
Share your code 