[logback-user] SizeBasedTriggeringPolicy + RollingFileAppender bizarrely slow in certain cases on Windows

[mpderbec]

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