[logback-dev] Question: AsyncAppender's thread safety?

[Aaron Curley]

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 at 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 at 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 at qos.ch
>>> http://mailman.qos.ch/mailman/listinfo/logback-dev
>>>
>> _______________________________________________
>> logback-dev mailing list
>> logback-dev at qos.ch
>> http://mailman.qos.ch/mailman/listinfo/logback-dev
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20160306/34a83cf8/attachment-0001.html>