Re: [logback-user] Looking for details about AsyncAppender properties
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@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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
I should have mentioned that I’ve already read that page, and multiple times. My question about “queueSize” is specific to memory allocation. I understand the blocking behavior. When I saw that the default value was 256, and my team was proposing a value of 100000, I wanted to be sure that didn’t have any unexpected consequences, like if that number represents the relative size of a pre-allocated buffer, that would be unexpected. I think this is unlikely, but the documentation doesn’t say anything about this. Concerning “includeCallerData”, so it consists of the file and line of the caller. I see in the documentation for PatternLayout. I assume this is potentially the only way that information would be utilized? From: logback-user <logback-user-bounces@qos.ch> On Behalf Of David Roussel Sent: Saturday, May 22, 2021 12:07 AM To: logback users list <logback-user@qos.ch> Subject: Re: [logback-user] Looking for details about AsyncAppender properties Hi David, As documented in http://logback.qos.ch/manual/appenders.html<https://urldefense.com/v3/__http:/logback.qos.ch/manual/appenders.html__;!!BhdT!07aKoZX2Fw7v5BkqgjGU20O5MKOiqa0FwqVQttt4o3lHAOG49nbJiefncP1bJg$> 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@att.com<mailto:dk068x@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@qos.ch<mailto:logback-user@qos.ch> http://mailman.qos.ch/mailman/listinfo/logback-user<https://urldefense.com/v3/__http:/mailman.qos.ch/mailman/listinfo/logback-user__;!!BhdT!07aKoZX2Fw7v5BkqgjGU20O5MKOiqa0FwqVQttt4o3lHAOG49nbJiecNrKH5WA$>
It’s been many years since I read the code. But I seem to remember it’s quite straight forward and just uses a java ArrayList, which will size itself dynamically. But you’d best just read it yourself. IMHO the lock usage in the blocking queue isn’t great and could be more efficient. But it does the job, and by not blocking on network IO it’s always given me a good speed up. In the last project where is used logback I turned it on by default at the begging of the project because it was such a clear win based on my past experience. The default settings are fine. Setting a very high limit would only be justified if you have a lot of memory and are expecting to have occasional very slow periods of IO. But given you are writing to stdout, this will depend on the behaviour of the log stream consumer abs how much buffering it does. I would expect any decent logging adapter to be built to cope with network interruptions and buffer accordingly. Dave
You may get better behavior with logstash logback encoder’s disruptive based appender, if performance is a concern.
On May 22, 2021, at 12:32 PM, David Roussel <nabble@diroussel.xsmail.com> wrote:
It’s been many years since I read the code. But I seem to remember it’s quite straight forward and just uses a java ArrayList, which will size itself dynamically. But you’d best just read it yourself.
IMHO the lock usage in the blocking queue isn’t great and could be more efficient. But it does the job, and by not blocking on network IO it’s always given me a good speed up.
In the last project where is used logback I turned it on by default at the begging of the project because it was such a clear win based on my past experience.
The default settings are fine. Setting a very high limit would only be justified if you have a lot of memory and are expecting to have occasional very slow periods of IO.
But given you are writing to stdout, this will depend on the behaviour of the log stream consumer abs how much buffering it does.
I would expect any decent logging adapter to be built to cope with network interruptions and buffer accordingly.
Dave _______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
-----Original Message----- From: logback-user <logback-user-bounces@qos.ch> On Behalf Of David Roussel Sent: Saturday, May 22, 2021 12:33 PM To: logback users list <logback-user@qos.ch> Subject: Re: [logback-user] Looking for details about AsyncAppender properties
It’s been many years since I read the code. But I seem to remember it’s quite straight forward and just uses a java ArrayList, which will size itself dynamically. But you’d best just read it yourself.
Ok, well, good idea. What I found could potentially be a problem, but it depends on the situation. It is creating an ArrayBlockingQueue, and passing the queue size to the constructor, which allocates an Object array of that size, so I guess that will likely be 800k for each AsyncAppender (queueSize of 100000). That could be significant, or not.
IMHO the lock usage in the blocking queue isn’t great and could be more efficient. But it does the job, and by not blocking on network IO it’s always given me a good speed up.
In the last project where is used logback I turned it on by default at the begging of the project because it was such a clear win based on my past experience.
The default settings are fine. Setting a very high limit would only be justified if you have a lot of memory and are expecting to have occasional very slow periods of IO.
But given you are writing to stdout, this will depend on the behaviour of the log stream consumer abs how much buffering it does.
I would expect any decent logging adapter to be built to cope with network interruptions and buffer accordingly.
Dave _______________________________________________ logback-user mailing list logback-user@qos.ch https://urldefense.com/v3/__http://mailman.qos.ch/mailman/listinfo/logba ck- user__;!!BhdT!xxdh0wF7WsxDh76ZH4dqOpy5OVu2GeuW2uHh1qcirY_VVsw Ma_N2YdhXJwcl6g$
David
On 23 May 2021, at 01:24, KARR, DAVID <dk068x@att.com> wrote:
I guess that will likely be 800k for each AsyncAppender (queueSize of 100000). That could be significant, or not.
That’s just for the array. The data will be bigger. But weather it’s worth it depends on the risk of data loss of logs. And the problem with loosing log lines is that it is hard to spot. Most teams never look for missing log lines. And if they thought some were missing it would be hard to prove if and why it occurred. So what do you use logs for? Diagnostics in case of a problem? Or do they feed MI reporting? David
You can report failure to log with an appender listener. https://github.com/logstash/logstash-logback-encoder/blob/master/src/main/ja... https://github.com/logstash/logstash-logback-encoder
On May 23, 2021, at 2:26 AM, David Roussel <nabble@diroussel.xsmail.com> wrote:
David
On 23 May 2021, at 01:24, KARR, DAVID <dk068x@att.com> wrote:
I guess that will likely be 800k for each AsyncAppender (queueSize of 100000). That could be significant, or not.
That’s just for the array. The data will be bigger. But weather it’s worth it depends on the risk of data loss of logs.
And the problem with loosing log lines is that it is hard to spot. Most teams never look for missing log lines. And if they thought some were missing it would be hard to prove if and why it occurred.
So what do you use logs for? Diagnostics in case of a problem? Or do they feed MI reporting?
David
_______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
I am now at the point of attempting to implement this listener, but I’m having trouble with it. With some elisions, my logback.xml looks like this: <?xml version="1.0" encoding="UTF-8"?> <configuration scan="true" scanPeriod="5 seconds" debug="true"> <include file=".../baselogback.xml"/> <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"> <appender-ref ref="STDOUT" /> <listener class="net.logstash.logback.appender.listener.FailureSummaryLoggingAppenderListener"/> <discardingThreshold>0</discardingThreshold> <queueSize>256</queueSize> <includeCallerData>false</includeCallerData> <neverBlock>false</neverBlock> </appender> <logger name="..." level="DEBUG" additivity="false"> <appender-ref ref="ASYNC"/> </logger> <logger name="..." level="DEBUG" additivity="false"> <appender-ref ref="STDOUT"/> </logger> <root level="INFO"> <appender-ref ref="STDOUT"/> </root> </configuration> I tested the async appender before I added the listener, and it seemed to be basically working (although I’m not certain how I verify from the logs that it’s actually asynchronous). I then added the listener as above. When I start my service with this, I get the following: Logging system failed to initialize using configuration from '.../logback.xml' java.lang.IllegalStateException: Logback configuration error detected: ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:101 - no applicable action for [listener], current ElementPath is [[configuration][appender][listener]] ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:101 - no applicable action for [listener], current ElementPath is [[configuration][appender][listener]] at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:169) I don’t understand what is wrong here. From: logback-user <logback-user-bounces@qos.ch> On Behalf Of Will Sargent Sent: Sunday, May 23, 2021 3:50 AM To: logback users list <logback-user@qos.ch> Subject: Re: [logback-user] Looking for details about AsyncAppender properties You can report failure to log with an appender listener. https://github.com/logstash/logstash-logback-encoder/blob/master/src/main/java/net/logstash/logback/appender/listener/FailureSummaryLoggingAppenderListener.java<https://urldefense.com/v3/__https:/github.com/logstash/logstash-logback-encoder/blob/master/src/main/java/net/logstash/logback/appender/listener/FailureSummaryLoggingAppenderListener.java__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5SffDv0sA$> https://github.com/logstash/logstash-logback-encoder<https://urldefense.com/v3/__https:/github.com/logstash/logstash-logback-encoder__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5RNGmCTQA$> On May 23, 2021, at 2:26 AM, David Roussel <nabble@diroussel.xsmail.com<mailto:nabble@diroussel.xsmail.com>> wrote: David On 23 May 2021, at 01:24, KARR, DAVID <dk068x@att.com<mailto:dk068x@att.com>> wrote: I guess that will likely be 800k for each AsyncAppender (queueSize of 100000). That could be significant, or not. That’s just for the array. The data will be bigger. But weather it’s worth it depends on the risk of data loss of logs. And the problem with loosing log lines is that it is hard to spot. Most teams never look for missing log lines. And if they thought some were missing it would be hard to prove if and why it occurred. So what do you use logs for? Diagnostics in case of a problem? Or do they feed MI reporting? David _______________________________________________ logback-user mailing list logback-user@qos.ch<mailto:logback-user@qos.ch> http://mailman.qos.ch/mailman/listinfo/logback-user<https://urldefense.com/v3/__http:/mailman.qos.ch/mailman/listinfo/logback-user__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5QylXlM7w$>
Ok, so it appears that this listener can only work with tcp appenders, not console appenders. Is there a path forward for building a listener that has similar functionality, but that works with console appenders? From: logback-user <logback-user-bounces@qos.ch> On Behalf Of KARR, DAVID Sent: Wednesday, June 16, 2021 12:55 PM To: logback users list <logback-user@qos.ch> Subject: Re: [logback-user] Looking for details about AsyncAppender properties ***Security Advisory: This Message Originated Outside of AT&T *** Reference http://cso.att.com/EmailSecurity/IDSP.html for more information. I am now at the point of attempting to implement this listener, but I’m having trouble with it. With some elisions, my logback.xml looks like this: <?xml version="1.0" encoding="UTF-8"?> <configuration scan="true" scanPeriod="5 seconds" debug="true"> <include file=".../baselogback.xml"/> <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"> <appender-ref ref="STDOUT" /> <listener class="net.logstash.logback.appender.listener.FailureSummaryLoggingAppenderListener"/> <discardingThreshold>0</discardingThreshold> <queueSize>256</queueSize> <includeCallerData>false</includeCallerData> <neverBlock>false</neverBlock> </appender> <logger name="..." level="DEBUG" additivity="false"> <appender-ref ref="ASYNC"/> </logger> <logger name="..." level="DEBUG" additivity="false"> <appender-ref ref="STDOUT"/> </logger> <root level="INFO"> <appender-ref ref="STDOUT"/> </root> </configuration> I tested the async appender before I added the listener, and it seemed to be basically working (although I’m not certain how I verify from the logs that it’s actually asynchronous). I then added the listener as above. When I start my service with this, I get the following: Logging system failed to initialize using configuration from '.../logback.xml' java.lang.IllegalStateException: Logback configuration error detected: ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:101<mailto:ch.qos.logback.core.joran.spi.Interpreter@5:101> - no applicable action for [listener], current ElementPath is [[configuration][appender][listener]] ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:101<mailto:ch.qos.logback.core.joran.spi.Interpreter@5:101> - no applicable action for [listener], current ElementPath is [[configuration][appender][listener]] at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:169) I don’t understand what is wrong here. From: logback-user <logback-user-bounces@qos.ch<mailto:logback-user-bounces@qos.ch>> On Behalf Of Will Sargent Sent: Sunday, May 23, 2021 3:50 AM To: logback users list <logback-user@qos.ch<mailto:logback-user@qos.ch>> Subject: Re: [logback-user] Looking for details about AsyncAppender properties You can report failure to log with an appender listener. https://github.com/logstash/logstash-logback-encoder/blob/master/src/main/java/net/logstash/logback/appender/listener/FailureSummaryLoggingAppenderListener.java<https://urldefense.com/v3/__https:/github.com/logstash/logstash-logback-encoder/blob/master/src/main/java/net/logstash/logback/appender/listener/FailureSummaryLoggingAppenderListener.java__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5SffDv0sA$> https://github.com/logstash/logstash-logback-encoder<https://urldefense.com/v3/__https:/github.com/logstash/logstash-logback-encoder__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5RNGmCTQA$> On May 23, 2021, at 2:26 AM, David Roussel <nabble@diroussel.xsmail.com<mailto:nabble@diroussel.xsmail.com>> wrote: David On 23 May 2021, at 01:24, KARR, DAVID <dk068x@att.com<mailto:dk068x@att.com>> wrote: I guess that will likely be 800k for each AsyncAppender (queueSize of 100000). That could be significant, or not. That’s just for the array. The data will be bigger. But weather it’s worth it depends on the risk of data loss of logs. And the problem with loosing log lines is that it is hard to spot. Most teams never look for missing log lines. And if they thought some were missing it would be hard to prove if and why it occurred. So what do you use logs for? Diagnostics in case of a problem? Or do they feed MI reporting? David _______________________________________________ logback-user mailing list logback-user@qos.ch<mailto:logback-user@qos.ch> http://mailman.qos.ch/mailman/listinfo/logback-user<https://urldefense.com/v3/__http:/mailman.qos.ch/mailman/listinfo/logback-user__;!!BhdT!zwLb2IBXPlOE_S18efHOAwlRxSrCqtisf48mb3qFZWAaIii4Z9ziT5QylXlM7w$>
participants (3)
-
David Roussel -
KARR, DAVID -
Will Sargent