[logback-user] Logback becomes excruciatingly slow during rollover

Thu May 26 14:34:52 UTC 2016

Hello Ceki,

Thank you for the suggestion. We added the debug="true" option and Logback gave us a clue about the problem:

ERROR in ch.qos.logback.core.rolling.RollingFileAppender[DS_QUERY_PROFILE_FILE] - openFile(sD:/logs/query_profile_dataservice.log,true) call failed. java.io.FileNotFoundException: sD:\logs\query_profile_dataservice.log (The filename, directory name, or volume label syntax is incorrect)

Apparently, when somebody modified the logging configuration, they added a redundant 's' at the beginning of the log file path. This caused Logback to fall back to letting that appender use the log file used by another appender. In the end, two different appenders started using the same log file (by using Process Explorer, we also saw that the same JVM was holding *two* handles to file D:\logs\product.log), and eventually, when Logback tried to roll over the log files, the problems started. We could see the following in the logs:

Failed to rename file [D:\logs\product.log] to [D:\logs\product_0.log].

Normally, only one file handle to file D:\logs\product.log is used. When I added a similar 's' in a test environment, I got two file handles too, and eventually Logback became super-slow.

We asked the customer to remove the redundant 's' and to restart the product and then to wait until the next roll-over and to tell us if things were okay. I just received the following feedback from our support people:

"Customer has been running with new serviceability.xml file since last change. So far, it appears the files are rolling over and there is no longer any slowness once the file reaches 50mb. We'll continue to monitor thru next week, but it appears the issue may have been resolved by fixing the file."

It will be great if Logback gets fixed, so that:

1. Two appenders should never write to the same file, or if they do, then the code should be fixed in such a way that this causes no problems
2. Logback should not become so slow. Perhaps some non-(b)locking algorithm should be used, if possible.

Thank you for your help!

----------------------------------------------------------------------

Hello Vesuvius,

Enabling logback's internal status messages [1] is an investigative step
of *first* resort. I would start there.

Any computing system can be brought to its knees if sufficiently
stressed. From what I could gather from your previous messages, the
application in question generates massive amounts of logs. If so, my
suggestion would be to reduce logging output by setting the root logger
level to WARN for example.

As a side note, I would suggest using SizeAndTimeBasedRollingPolicy [2]
which provides a much nicer archiving policy than the
FixedWindowRollingPolicy+SizeBasedTriggeringPolicy combination.

--
Ceki

[1] http://logback.qos.ch/manual/configuration.html#automaticStatusPrinting

[2]
http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy

On 5/11/2016 12:02, Vesuvius Prime wrote:

> Hi,

> Thank you for the suggestion. This was the first thing I had
> suggested to the customer during the live session with them but then
> they said they didn't want to be a "testbed" for us, so they didn't do
> it. Now I asked our support guys to ask the customer again to do this
> and this time the customer agreed. After waiting a while for the logs
> to roll over, here's the feedback:
>
> "Hello, Customer just provided an update.  Log file is not rolling
> over, however it has grown to over 90mb, but the [product] has not
> slowed down."
>
> So, there's an improvement -- at least now we're not becoming
> unusable due to excessive slowness. However, the log grows without a
> limit. The bottom line is that this is an improvement, but not a
> solution.
>
> I would still love somebody with deep knowledge of Logback
> (presumably its authors) to provide some feedback here. For example,
> if this is a known problem and it has been solved in some version of
> Logback, we may go ahead an modify the Virgo server to use that
> version. Alternatively, if Logback is unreliable, we may have to
> switch to some other logging framework. I've been seeing various
> reports about rollover problems, even in this mail list. We can't
> afford to lose customers due to logging. Besides, this creates a
> really bad image to Logback itself.
>
>  Thank you for reading this.
>

------------------------------

Message: 2
Date: Thu, 12 May 2016 08:25:56 +0100
From: David Roussel <nabble at diroussel.xsmail.com>
To: logback users list <logback-user at qos.ch>
Subject: Re: [logback-user] Change FixedWindowRollingPolicy rolling
        behaviour
Message-ID:
        <1B78DD98-75AA-43AB-BEA5-D291673026C2 at diroussel.xsmail.com>
Content-Type: text/plain; charset=us-ascii

Hi DK,

It's not clear what you are asking for.

Currently the files are renamed in reverse order so that there is no name clash. What other strategy are you suggesting?

David

> On 27 Apr 2016, at 15:05, DK <desmond.kirrane at gmail.com> wrote:
>
> Hi can I change FixedWindowRollingPolicy to rollover as follows:
>
> foo.log active log file
> foo1.log first rollover
> foo2.log second rollover
> foo3.log third rollover
>
> Current behaviour is second rollover. foo1.log is renamed as foo2.log.
> foo.log is renamed as foo1.log
>
>
>
> --
> View this message in context: http://logback.10977.n7.nabble.com/Change-FixedWindowRollingPolicy-rolling-behaviour-tp14954.html
> Sent from the Users mailing list archive at Nabble.com.
> _______________________________________________
> logback-user mailing list
> logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user

------------------------------

Subject: Digest Footer

_______________________________________________
logback-user mailing list
logback-user at qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user

------------------------------

End of logback-user Digest, Vol 56, Issue 4
*******************************************