logback-user

Download

logback-user@qos.ch

June 2021

2 participants
2 discussions

Unsuccessful delete in FixedWindowRollingPolicy causes disk trashing and cpu at 100%
by Carl-Erik Kopseng 23 Jun '21

23 Jun '21

Hi, for some weeks we have observed some really mysterious behavior when enabling one of our appenders. This appender was configured specially to use the `FixedWindowRollingPolicy`. What we observed, was that after some time of debug logging, the CPU would suddenly hit the roof and have at least one core fully pegged at 100%. Using Jprofiler we found the issue to be various cases of `logger.debug()` that would be used by this special appender. Disabling the appender immediately fixed the issue (as we have `scan=true`) I debugged this yesterday and found the answer partly in the logs and in the logback code. This is the line that basically shows the issue: if (!file2zip.delete()) { addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip + "].", this)); } The logs were full of this and I also found references to this online. I documented the entire process and findings in this repo: https://github.com/fatso83/logback-bug. The repo also contains a minimal attempt at recreating what I saw on the Windows servers on my local machine. I was unable to reproduce this locally, which I kind of need in order to fix this bug. So, I was just wondering if any of you had any tips? What could cause the file to be "locked" / prevented from being deleted? Would it be enough if someone had a read-handle on the file, for instance a log reader like `glogg <https://glogg.bonnefon.org>`? I made sure to close my own programs when looking at this, but there are multiple users that look at these logs. There is a single JVM running this app. -- Carl-Erik Kopseng Senior developer Diffia AS

1 1

Re: [logback-user] Looking for details about AsyncAppender properties
by David Roussel 16 Jun '21

16 Jun '21

Hi David, As documented in http://logback.qos.ch/manual/appenders.html The queue in async appender is a blocking queue. So if it fills up, then the application code will block until there is space in the queue. Burg that blocking will only occur for error messages as mentioned in the above linked page; > Note that by default,AsyncAppender will drop events of level TRACE, DEBUG and INFO if its queue is 80% full. This strategy has an amazingly favorable effect on performance at the cost of event loss. So this is a reason to use a large queue size, if you want to avoid loosing info messages under high load. As for ‘ includeCallerData’, this including information about the caller of the logger, like line number and file. This takes us more memory, and not all for matters use it. David > On 22 May 2021, at 04:21, KARR, DAVID <dk068x(a)att.com> wrote: > I'm investigating what the consequences will be of changing some of our high volume logging calls to use an AsyncAppender instead of a synchronous appender. Our services run in a k8s container, so they are ultimately writing to stdout, although other processes are aggregating that log output to Splunk or ELK. > > I understand the basic idea of what the AsyncAppender will do, but I have some questions about the impact of some property settings which I cannot find details about in the documentation. > > I'm mostly interested in the "queueSize" and "includeCallerData" properties. > > Concerning "queueSize", I know it is the limit to the size of the input queue, but how exactly is that parameter utilized? Is any memory allocated based on that queue size at startup, or is it simply the limit of a dynamically expanding list? The default queue size is apparently 256. A team in our organization is planning to set this to a very large number, like 100000. Obviously, there would be considerable impact if the queue really reached that size, and I understand that. > > Concerning "includeCallerData", I understand this even less. How is this "caller data" used? What does it really represent? What is the impact of this being included or not included? I tried running tests with one service with the main high volume appender being set to use the sync appender, and then the async appender. I didn't really notice any changes in the output. > _______________________________________________ > logback-user mailing list > logback-user(a)qos.ch > http://mailman.qos.ch/mailman/listinfo/logback-user

3 8