Question: AsyncAppender's thread safety?
Hello all, I’m most likely missing something here, but reviewing AsyncAppender in logback classic 1.1.6, I’m not sure how it’s entirely thread safe, especially with respect to the “started” flag in its grandparent class (UnsynchronizedAppenderBase). In particular, the doAppend() method in UnsynchronizedAppenderBase checks the “started” boolean member's value (line 72) before actually appending, yet, no synchronization primitives are (or appear to be, from my perspective) used to ensure that the “started” member is visible to all threads once it is updated via start(). I would have thought that AsyncAppender would have inherited from AppenderBase (which is thread safe and does mark “started” as volatile) rather than extending UnsynchronizedAppenderBase. Baring this, I would have thought that the “started” member would be “overridden” with AsyncAppender’s own volatile version of this flag or access to started would be protected with a lock. As a result, isn’t it possible that if one thread calls start() and then another thread immediately logs something (calling doAppend()), the logging thread would see “started” as false? Wouldn’t this result in “skipping” certain log messages entirely (if the appender was very recently started)? I think I must be missing something. Can someone clarify how this works? Thanks in advance! Best Regards, Aaron Curley accwebs@gmail.com P. S. I would have also expected start() and stop() (in AsyncAppender or its parent) to be overridden to introduce synchronization, since AsyncAppender is generally used by multiple threads. Right now, it appears that start & stop operations are not idempotent nor are multiple (simultaneous) calls prevented.
Hi Aaron, Comments inline. On 3/2/2016 23:40, Aaron Curley wrote:
Hello all,
I’m most likely missing something here, but reviewing AsyncAppender in logback classic 1.1.6, I’m not sure how it’s entirely thread safe, especially with respect to the “started” flag in its grandparent class (UnsynchronizedAppenderBase).
In particular, the doAppend() method in UnsynchronizedAppenderBase checks the “started” boolean member's value (line 72) before actually appending, yet, no synchronization primitives are (or appear to be, from my perspective) used to ensure that the “started” member is visible to all threads once it is updated via start(). I would have thought that AsyncAppender would have inherited from AppenderBase (which is thread safe and does mark “started” as volatile) rather than extending UnsynchronizedAppenderBase. Baring this, I would have thought that the “started” member would be “overridden” with AsyncAppender’s own volatile version of this flag or access to started would be protected with a lock.
As a result, isn’t it possible that if one thread calls start() and then another thread immediately logs something (calling doAppend()), the logging thread would see “started” as false? Wouldn’t this result in “skipping” certain log messages entirely (if the appender was very recently started)?
You are absolutely right. Events generated in other threads could be lost until the new value (true) of start was propagated to those threads. Good catch.
I think I must be missing something. Can someone clarify how this works? Thanks in advance!
Best Regards,
Aaron Curley accwebs@gmail.com
P. S. I would have also expected start() and stop() (in AsyncAppender or its parent) to be overridden to introduce synchronization, since AsyncAppender is generally used by multiple threads. Right now, it appears that start & stop operations are not idempotent nor are multiple (simultaneous) calls prevented.
The idempotency could be enforced by introducing a check if(isStarted()) {return;} at the top of the start() method. But again, good catch. Here are a couple of questions for you. 1) How would you write a test case for asserting the correct propagation of start? 2) What would be the computational cost of having a volatile start? 3) What would you suggest to minimize the cost if the cost was elevated? Best regards, -- Ceki
Hi again, Would you please create a JIRA issue for the problem you raised on the mailing list? -- Ceki On 3/3/2016 9:16, Ceki Gulcu wrote:
Hi Aaron,
Comments inline.
On 3/2/2016 23:40, Aaron Curley wrote:
Hello all,
I’m most likely missing something here, but reviewing AsyncAppender in logback classic 1.1.6, I’m not sure how it’s entirely thread safe, especially with respect to the “started” flag in its grandparent class (UnsynchronizedAppenderBase).
In particular, the doAppend() method in UnsynchronizedAppenderBase checks the “started” boolean member's value (line 72) before actually appending, yet, no synchronization primitives are (or appear to be, from my perspective) used to ensure that the “started” member is visible to all threads once it is updated via start(). I would have thought that AsyncAppender would have inherited from AppenderBase (which is thread safe and does mark “started” as volatile) rather than extending UnsynchronizedAppenderBase. Baring this, I would have thought that the “started” member would be “overridden” with AsyncAppender’s own volatile version of this flag or access to started would be protected with a lock.
As a result, isn’t it possible that if one thread calls start() and then another thread immediately logs something (calling doAppend()), the logging thread would see “started” as false? Wouldn’t this result in “skipping” certain log messages entirely (if the appender was very recently started)?
You are absolutely right. Events generated in other threads could be lost until the new value (true) of start was propagated to those threads. Good catch.
I think I must be missing something. Can someone clarify how this works? Thanks in advance!
Best Regards,
Aaron Curley accwebs@gmail.com
P. S. I would have also expected start() and stop() (in AsyncAppender or its parent) to be overridden to introduce synchronization, since AsyncAppender is generally used by multiple threads. Right now, it appears that start & stop operations are not idempotent nor are multiple (simultaneous) calls prevented.
The idempotency could be enforced by introducing a check if(isStarted()) {return;} at the top of the start() method. But again, good catch.
Here are a couple of questions for you.
1) How would you write a test case for asserting the correct propagation of start? 2) What would be the computational cost of having a volatile start? 3) What would you suggest to minimize the cost if the cost was elevated?
Best regards,
-- Ceki
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
Hi Ceki, Thanks for your responses. Absolutely; I'll create a JIRA shortly. As to your question about a test case, I'll see if I can get something working over the next 1-2 days. Unfortunately, even if I am successful, the test case is likely to only sometimes detect this particular problem (since threads are generally not deterministic). The performance questions (i.e. the costs of volatile) are a bit harder to answer and I'm not sure I'm presently equipped to execute the necessary performance testing. I'll give this more thought. Aaron On 3/3/2016 3:13 AM, Ceki Gulcu wrote:
Hi again,
Would you please create a JIRA issue for the problem you raised on the mailing list?
-- Ceki
On 3/3/2016 9:16, Ceki Gulcu wrote:
Hi Aaron,
Comments inline.
On 3/2/2016 23:40, Aaron Curley wrote:
Hello all,
I’m most likely missing something here, but reviewing AsyncAppender in logback classic 1.1.6, I’m not sure how it’s entirely thread safe, especially with respect to the “started” flag in its grandparent class (UnsynchronizedAppenderBase).
In particular, the doAppend() method in UnsynchronizedAppenderBase checks the “started” boolean member's value (line 72) before actually appending, yet, no synchronization primitives are (or appear to be, from my perspective) used to ensure that the “started” member is visible to all threads once it is updated via start(). I would have thought that AsyncAppender would have inherited from AppenderBase (which is thread safe and does mark “started” as volatile) rather than extending UnsynchronizedAppenderBase. Baring this, I would have thought that the “started” member would be “overridden” with AsyncAppender’s own volatile version of this flag or access to started would be protected with a lock.
As a result, isn’t it possible that if one thread calls start() and then another thread immediately logs something (calling doAppend()), the logging thread would see “started” as false? Wouldn’t this result in “skipping” certain log messages entirely (if the appender was very recently started)?
You are absolutely right. Events generated in other threads could be lost until the new value (true) of start was propagated to those threads. Good catch.
I think I must be missing something. Can someone clarify how this works? Thanks in advance!
Best Regards,
Aaron Curley accwebs@gmail.com
P. S. I would have also expected start() and stop() (in AsyncAppender or its parent) to be overridden to introduce synchronization, since AsyncAppender is generally used by multiple threads. Right now, it appears that start & stop operations are not idempotent nor are multiple (simultaneous) calls prevented.
The idempotency could be enforced by introducing a check if(isStarted()) {return;} at the top of the start() method. But again, good catch.
Here are a couple of questions for you.
1) How would you write a test case for asserting the correct propagation of start? 2) What would be the computational cost of having a volatile start? 3) What would you suggest to minimize the cost if the cost was elevated?
Best regards,
-- Ceki
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
Hi Ceki, I just made an initial attempt to improve AsyncAppender's thread safety. I provided a link to the commit in my fork (see the latest comment on LOGBACK-1148). This is just an initial shot at fixing the more obvious problems. Of course, I think more work/thought would be required before we could consider merging this. Overall, my approach was threefold: 1. make as much stuff final as possible (which ensures safe publication of values to all threads) 2. use locks to protect any mutable members that **did not** need to be accessed during a doAppend() event 3. make any remaining mutable members / member references volatile. For any volatile mutable object members, I also double-checked that the mutable object being referenced was thread safe. Thankfully, they appear to be so. A couple of specific notes: A. doAppend() can acquire locks, but only in cases of errors. There is no way to eliminate this synchronization due to the various counter variable increment operations that take place during error conditions. (Volatile only helps in cases of atomic operations) B. The trickiest part of my change is the stop() method -- my first instinct was to place all of stop()'s code inside a synchronized block (like with my changes to the other non-performance-critical pieces of code); however, I was worried about deadlocks resulting from the wait in worker.join() call and the worker potentially needing to acquire a lock (such as in an error condition). This would cause the worker to block until the worker.interrupt() call timed out (if worker.interrupt() was called within a synchronized block). To work around the problem, I created a "stopping" flag which I set in a synchronized block at the beginning of stop() and clear in another block at the end of stop(). In the middle of the two synchronized blocks, the call to worker.interrupt() occurs unsynchronized. At your convenience, can you take a look at what I did and send me any thoughts/feedback? Obviously, no rush on this. ;-) Best Regards, Aaron Curley On Thu, Mar 3, 2016 at 6:57 PM, Aaron Curley <accwebs@gmail.com> wrote:
Hi Ceki,
Thanks for your responses. Absolutely; I'll create a JIRA shortly.
As to your question about a test case, I'll see if I can get something working over the next 1-2 days. Unfortunately, even if I am successful, the test case is likely to only sometimes detect this particular problem (since threads are generally not deterministic).
The performance questions (i.e. the costs of volatile) are a bit harder to answer and I'm not sure I'm presently equipped to execute the necessary performance testing. I'll give this more thought.
Aaron
On 3/3/2016 3:13 AM, Ceki Gulcu wrote:
Hi again,
Would you please create a JIRA issue for the problem you raised on the mailing list?
-- Ceki
On 3/3/2016 9:16, Ceki Gulcu wrote:
Hi Aaron,
Comments inline.
On 3/2/2016 23:40, Aaron Curley wrote:
Hello all,
I’m most likely missing something here, but reviewing AsyncAppender in logback classic 1.1.6, I’m not sure how it’s entirely thread safe, especially with respect to the “started” flag in its grandparent class (UnsynchronizedAppenderBase).
In particular, the doAppend() method in UnsynchronizedAppenderBase checks the “started” boolean member's value (line 72) before actually appending, yet, no synchronization primitives are (or appear to be, from my perspective) used to ensure that the “started” member is visible to all threads once it is updated via start(). I would have thought that AsyncAppender would have inherited from AppenderBase (which is thread safe and does mark “started” as volatile) rather than extending UnsynchronizedAppenderBase. Baring this, I would have thought that the “started” member would be “overridden” with AsyncAppender’s own volatile version of this flag or access to started would be protected with a lock.
As a result, isn’t it possible that if one thread calls start() and then another thread immediately logs something (calling doAppend()), the logging thread would see “started” as false? Wouldn’t this result in “skipping” certain log messages entirely (if the appender was very recently started)?
You are absolutely right. Events generated in other threads could be lost until the new value (true) of start was propagated to those threads. Good catch.
I think I must be missing something. Can someone clarify how this works? Thanks in advance!
Best Regards,
Aaron Curley accwebs@gmail.com
P. S. I would have also expected start() and stop() (in AsyncAppender or its parent) to be overridden to introduce synchronization, since AsyncAppender is generally used by multiple threads. Right now, it appears that start & stop operations are not idempotent nor are multiple (simultaneous) calls prevented.
The idempotency could be enforced by introducing a check if(isStarted()) {return;} at the top of the start() method. But again, good catch.
Here are a couple of questions for you.
1) How would you write a test case for asserting the correct propagation of start? 2) What would be the computational cost of having a volatile start? 3) What would you suggest to minimize the cost if the cost was elevated?
Best regards,
-- Ceki
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
participants (2)
-
Aaron Curley -
Ceki Gulcu