<div dir="ltr"><div><div><div><div><div>Hi Ceki,<br><br></div>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).<br><br></div>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.<br><br></div><div>Overall, my approach was threefold:<br></div><div>1. make as much stuff final as possible (which ensures safe publication of values to all threads)<br></div><div>2. use locks to protect any mutable members that **did not** need to be accessed during a doAppend() event<br></div><div>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.<br><br><br></div><div>A couple of specific notes:<br><br></div><div>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)<br></div><div><br></div><div>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.<br><br></div><div><br></div>At your convenience, can you take a look at what I did and send me any thoughts/feedback? Obviously, no rush on this. ;-)<br><br></div>Best Regards,<br></div>Aaron Curley<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Mar 3, 2016 at 6:57 PM, Aaron Curley <span dir="ltr"><<a href="mailto:accwebs@gmail.com" target="_blank">accwebs@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi Ceki,<br>
<br>
Thanks for your responses. Absolutely; I'll create a JIRA shortly.<br>
<br>
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).<br>
<br>
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.<span class="HOEnZb"><font color="#888888"><br>
<br>
Aaron</font></span><div class="HOEnZb"><div class="h5"><br>
<br>
<br>
<br>
On 3/3/2016 3:13 AM, Ceki Gulcu wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
Hi again,<br>
<br>
Would you please create a JIRA issue for the problem you raised on the mailing list?<br>
<br>
-- <br>
Ceki<br>
<br>
On 3/3/2016 9:16, Ceki Gulcu wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hi Aaron,<br>
<br>
Comments inline.<br>
<br>
On 3/2/2016 23:40, Aaron Curley wrote:<br>
<br>
> Hello all,<br>
><br>
> I’m most likely missing something here, but reviewing AsyncAppender in<br>
> logback classic 1.1.6, I’m not sure how it’s entirely thread safe,<br>
> especially with respect to the “started” flag in its grandparent<br>
> class (UnsynchronizedAppenderBase).<br>
><br>
> In particular, the doAppend() method in UnsynchronizedAppenderBase<br>
> checks the “started” boolean member's value (line 72) before<br>
> actually appending, yet, no synchronization primitives are (or appear<br>
> to be, from my perspective) used to ensure that the “started”<br>
> member is visible to all threads once it is updated via start(). I<br>
> would have thought that AsyncAppender would have inherited from<br>
> AppenderBase (which is thread safe and does mark “started” as<br>
> volatile) rather than extending UnsynchronizedAppenderBase. Baring<br>
> this, I would have thought that the “started” member would be<br>
> “overridden” with AsyncAppender’s own volatile version of this<br>
> flag or access to started would be protected with a lock.<br>
><br>
> As a result, isn’t it possible that if one thread calls start() and<br>
> then another thread immediately logs something (calling doAppend()),<br>
> the logging thread would see “started” as false? Wouldn’t this<br>
> result in “skipping” certain log messages entirely (if the<br>
> appender was very recently started)?<br>
<br>
You are absolutely right. Events generated in other threads could be<br>
lost until the new value (true) of start was propagated to those<br>
threads. Good catch.<br>
<br>
> I think I must be missing something. Can someone clarify how this<br>
> works? Thanks in advance!<br>
><br>
> Best Regards,<br>
><br>
> Aaron Curley<br>
> <a href="mailto:accwebs@gmail.com" target="_blank">accwebs@gmail.com</a><br>
><br>
> P. S. I would have also expected start() and stop() (in<br>
> AsyncAppender or its parent) to be overridden to introduce<br>
> synchronization, since AsyncAppender is generally used by multiple<br>
> threads. Right now, it appears that start & stop operations are not<br>
> idempotent nor are multiple (simultaneous) calls prevented.<br>
<br>
The idempotency could be enforced by introducing a check if(isStarted())<br>
{return;} at the top of the start() method. But again, good catch.<br>
<br>
Here are a couple of questions for you.<br>
<br>
1) How would you write a test case for asserting the correct propagation<br>
of start?<br>
2) What would be the computational cost of having a volatile start?<br>
3) What would you suggest to minimize the cost if the cost was elevated?<br>
<br>
Best regards,<br>
<br>
-- <br>
Ceki<br>
<br>
_______________________________________________<br>
logback-dev mailing list<br>
<a href="mailto:logback-dev@qos.ch" target="_blank">logback-dev@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-dev" rel="noreferrer" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-dev</a><br>
</blockquote>
_______________________________________________<br>
logback-dev mailing list<br>
<a href="mailto:logback-dev@qos.ch" target="_blank">logback-dev@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-dev" rel="noreferrer" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-dev</a><br>
</blockquote>
<br>
</div></div></blockquote></div><br></div>