SizeBasedTriggeringPolicy + RollingFileAppender bizarrely slow in certain cases on Windows

We use the SizeBasedTriggeringPolicy and RollingFileAppender. We had reports of our application server on Windows slowing to a crawl, and after many hours debugging, discovered that it was the /content of the current log file/ that was causing each of LogBack's write operations to take several hundred milliseconds (instead of 5ms or so). Our log output is relatively verbose, so that meant our application was taking minutes to do simple operations if it was under load. It was a very rare occurrence, but when it happened, our application became useless. We could easily reproduce or eliminate the slowness by altering the content at the beginning of the log file. Namely, if we take all the dollar-sign characters ($) out of the first 200 lines, the slowness does not occur. Add them back and the slowness comes back immediately. We were able to do this without restarting our application, just by altering the content on the fly with Notepad++. I know this sounds crazy. So we created a tiny Java project that mimicks the calls that Logback makes with this triggering policy and appender. Namely, it retrieves the file length while simultaneously keeping a FileOutputStream object open for writing. It's the File.length() call that becomes slow. The project is posted here <https://github.com/seeq12/log-slowness> . You can see the code and read our commentary here <https://github.com/seeq12/log-slowness/blob/master/src/ShowLogSlowness.java> . It's pretty easy to clone the repo and run the Java command if you want to see this for yourself. This reproduced on 100% of our Windows environments (desktops, laptops, VMs). It does not reproduce on OSX. You can diff the two "seed" log files (fast.log and slow.log) and you'll see how little they differ. This is obviously not Logback's fault but Logback (and other logging libraries) would suffer nonetheless. I'm posting to this mailing list in case anyone has seen this and can offer insight / advice. -- Sent from: http://logback.10977.n7.nabble.com/Users-f3.html

Hey folks, this turned out to be the fault of Windows Defender, the anti-virus capability built into Windows. Read more here if you're interested: https://social.msdn.microsoft.com/Forums/windowsdesktop/en-US/2c21d5ce-2278-... We're going to investigate how to add ourselves to an exclusion list for Windows Defender. -- Sent from: http://logback.10977.n7.nabble.com/Users-f3.html

Hi Mark, Thank you for your last two posts. The small ShowLogSlowness.java stand alone java application makes it easy to understand the problem. I found it very helpful. As a wise man once said, "It's always the anti-virus." :-) Glad the problem has been diagnosed properly. Nice work. Cheers, -- Ceki On 23.10.2017 17:58, mpderbec wrote:
Hey folks, this turned out to be the fault of Windows Defender, the anti-virus capability built into Windows. Read more here if you're interested:
https://social.msdn.microsoft.com/Forums/windowsdesktop/en-US/2c21d5ce-2278-...
We're going to investigate how to add ourselves to an exclusion list for Windows Defender.
participants (2)
-
Ceki Gulcu
-
mpderbec