<div dir="ltr">Hi Champion,<div><br></div><div>Very interesting research on how the software interaction with the hardware can have performance implications beyond the algorithmic design.It might be interesting to try the disruptor pattern for other areas as well. </div>
<div><br></div><div>Regards,</div><div><br></div><div>Mike</div></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Fri, Mar 7, 2014 at 2:36 AM, champion <span dir="ltr"><<a href="mailto:champion@163.com" target="_blank">champion@163.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><u></u>
<div style="MARGIN:10px">
<div>Thank you for indicating the error ,I've update readme now</div>
<hr style="WIDTH:210px;min-height:1px" align="left" color="#b5c4df" size="1">
<div><span>champion</span></div>
<div> </div>
<div style="BORDER-BOTTOM:medium none;BORDER-LEFT:medium none;PADDING-BOTTOM:0cm;PADDING-LEFT:0cm;PADDING-RIGHT:0cm;BORDER-TOP:#b5c4df 1pt solid;BORDER-RIGHT:medium none;PADDING-TOP:3pt">
<div style="padding-right:8px;padding-left:8px;padding-top:8px;font-size:12px;background:#efefef;font-family:tahoma;padding-bottom:8px">
<div><b>From:</b> <a href="mailto:nabble@diroussel.xsmail.com" target="_blank">David
Roussel</a></div>
<div><b>Date:</b> <a href="tel:2014-03-07%C2%A015" value="+12014030715" target="_blank">2014-03-07 15</a>:18</div><div><div class="h5">
<div><b>To:</b> <a href="mailto:logback-user@qos.ch" target="_blank">logback users
list</a></div>
<div><b>Subject:</b> Re: [logback-user] AsyncAppenderBase not flushing
queue during JVM shutdown</div></div></div></div></div><div><div class="h5">
<div>
<div style>
<div>Very interesting. </div>
<div><br></div>
<div>This link in the page gives a 404: <a href="http://laforge49.github.io/JActor2/tutorials/core/gettingStarted.html" target="_blank">http://laforge49.github.io/JActor2/tutorials/core/gettingStarted.html</a><br><br>David</div>
<div><br>On 7 Mar 2014, at 06:42, champion <<a href="mailto:champion@163.com" target="_blank">champion@163.com</a>> wrote:<br><br></div>
<blockquote type="cite">
<div>
<div>I've writen a faster AsyncAppender which use disruptor,and run
stable in my project for years.the source is at <a href="https://github.com/cp149/jactor-logger" target="_blank">https://github.com/cp149/jactor-logger</a>,
Maybe it can give you some help.</div>
<div> </div>
<hr style="WIDTH:210px;min-height:1px" align="left" color="#b5c4df" size="1">
<div><span>champion</span></div>
<div> </div>
<div style="BORDER-BOTTOM:medium none;BORDER-LEFT:medium none;PADDING-BOTTOM:0cm;PADDING-LEFT:0cm;PADDING-RIGHT:0cm;BORDER-TOP:#b5c4df 1pt solid;BORDER-RIGHT:medium none;PADDING-TOP:3pt">
<div style="padding-right:8px;padding-left:8px;padding-top:8px;font-size:12px;background:#efefef;font-family:tahoma;padding-bottom:8px">
<div><b>From:</b> <a href="mailto:mike@coursescheduler.io" target="_blank">Michael
Reinhold</a></div>
<div><b>Date:</b> <a href="tel:2014-03-07%C2%A002" value="+12014030702" target="_blank">2014-03-07 02</a>:48</div>
<div><b>To:</b> <a href="mailto:logback-user@qos.ch" target="_blank">logback users
list</a></div>
<div><b>Subject:</b> Re: [logback-user] AsyncAppenderBase not flushing
queue during JVM shutdown</div></div></div>
<div>
<div style>
<div dir="ltr">Hi David, Chris,
<div><br></div>
<div>Thanks for the feedback. In the test case that I ran with the
AsyncAppender, LoggerContext.stop did not wait for the async appender to
finish flushing before exiting - the stop method returned immediately. I just
retested this scenario to be sure. My test should generate exactly 135 log
events (also going to a local file appender, so I can confirm that entries are
present or missing). Without the async appender I get all of the expected
events (at much lower throughput); with the async appender (using the call to
LoggerContext.stop prior to exiting) I get a variable number (generally less
than 20 events). It's possible that the lower latency of flushing to local
files results in the async appender being able to flush completely to disk
before the JVM exits, whereas the latency to Loggly is just too high. Queue
size probably also has an impact - I allow for a fairly large queue because
the penalty of falling back to synchronous logging for Loggly is large and my
logging tends to come in bursts.</div>
<div><br></div>
<div>If stop() did wait for async appenders to flush, that would improve the
situation. Although the use-case that involves shutdown hooks that want to log
would still need to be addressed. The only way that I can see that does
address allowing shutdown hooks to log is via a queue flushing shutdown hook
(requiring a call to LoggerContext.stop won't help for shutdown hooks or
applications that use JVM implicit shutdowns). My opinion is that a shutdown
hook can satisfy both needs with minimal impact to other classes or semantics
on how LoggerContext.stop functions. One hook per async appender would be
simple to implement and would also allow for parallel flushing of async
appender queues.<br></div>
<div><br></div>
<div>A default shutdown timeout as you described makes sense to me and fits
with what I was thinking for implementation of a shutdown hook.</div>
<div><br></div>
<div>I could probably throw together a quick and dirty implementation tonight
as a proof of concept. Thoughts?</div>
<div><br></div>
<div>Regards,</div>
<div><br></div>
<div>Mike Reinhold</div>
<div><br></div></div>
<div class="gmail_extra"><br><br>
<div class="gmail_quote">On Thu, Mar 6, 2014 at 1:01 PM, Chris Pratt <span dir="ltr"><<a href="mailto:thechrispratt@gmail.com" target="_blank">thechrispratt@gmail.com</a>></span> wrote:<br>
<blockquote style="BORDER-LEFT:#ccc 1px solid;MARGIN:0px 0px 0px 0.8ex;PADDING-LEFT:1ex" class="gmail_quote">
<div dir="ltr">Another option might be to require calling the
LoggerContext.stop when using AsyncAppender's. The stop method could
signal to the AsyncAppenders that they should drain their queue's and exit,
which would allow the application to shut down naturally (if the
AsyncAppenders aren't started as demon's)<span><font color="#888888">
<div> (*Chris*)</div></font></span></div>
<div>
<div>
<div class="gmail_extra"><br><br>
<div class="gmail_quote">On Thu, Mar 6, 2014 at 9:55 AM, David Roussel <span dir="ltr"><<a href="mailto:nabble@diroussel.xsmail.com" target="_blank">nabble@diroussel.xsmail.com</a>></span> wrote:<br>
<blockquote style="BORDER-LEFT:#ccc 1px solid;MARGIN:0px 0px 0px 0.8ex;PADDING-LEFT:1ex" class="gmail_quote">
<div>
<div>Mike,</div>
<div><br></div>
<div>I would expect the shutdown of logback to wait for async appenders to
drain their queues before we can consider the shutdown down. </div>
<div><br></div>
<div>I have used async appenders to provide faster logging when writing to
local files. And that's what I expected happens. </div>
<div><br></div>
<div>Of course there is the problem of waiting for too long. How about an
async appender has a default shutdown timeout which can be overridden by
config. So it can wait 2 seconds by default, but can be overridden to 30
seconds for the loggly usecase. </div>
<div><br></div>
<div>The simple solution is to put this all in AsyncAppender(Base), but if
we want to allow multiple async appenders to shutdown in parallel, then
the fix might involve more changes. <span><font color="#888888"><br><br>David</font></span></div>
<div>
<div>
<div><br>On 6 Mar 2014, at 12:51, Michael Reinhold <<a href="mailto:mike@coursescheduler.io" target="_blank">mike@coursescheduler.io</a>> wrote:<br><br></div>
<blockquote type="cite">
<div>
<div dir="ltr">Hi David,
<div><br></div>
<div>I forgot to mention this in my original note and it is a good
thought, but yes I have tried to cleanly shutdown Logback. Even when the
LogbackContext stop method is invoked prior to JVM exit, the async queue
is not flushed completely. When Logback is stopped cleanly, the async
worker thread exits the "waiting for events in the queue" while loop and
moves on to the "flush remaining elements from the queue" for loop
(confirmed by the info message when debug is enabled and via
breakpoint). Ultimately, because the thread is a daemon thread - this
process is still interrupted by JVM shutdown. There is no guarantee that
the async worker will get enough time to process all events.</div>
<div><br></div>
<div>From a theoretical standpoint, stopping Logback properly does not
solve flushing issues with the AsycAppender in a number of cases (it may
be fair to argue that it should not attempt to cover all of these
cases):</div>
<div>
<ul>
<li>Queue is relatively full or wrapped appender latency is high - the
async worker may not be able to finish processing the queued items
between when the LogbackContext.stop method is invoked and when the
JVM actually exits
</li><li>Implicit JVM exit upon end of last user thread - some applications
don't explicitly call System.exit but rather rely on implicit JVM
exit. In that case, where would you cleanly shutdown Logback? It can
probably be done, but would require an application redesign to avoid
reliance on implicit exit or some form of thread tracking thread.
</li><li>Shutdown hooks are used to clean up resources - some applications
have components or modules that need to clean up after themselves when
the JVM shuts down. Typically, shutdown hooks are used for this
purpose, however the AsyncAppender's worker thread is unable to
process queued events after shutdown has been initiated (while the
shutdown hooks are running). This also prevents shutdown hooks from
being able to log events
</li><li>Signal handling on *nix systems - signals can be sent to the
application for a number of reasons, most often to request graceful
shutdown or to terminate something that is non-responsive. If the
signal corresponds to something that generally means "graceful
shutdown" on the host system, normal cleanup routines should execute
in the application (typically implemented as shutdown hooks, so maybe
this is the same as the previous one). </li></ul>
<div>From a practical standpoint, I am running into the first and the
third scenarios. Even shutting down cleanly, the latency and queue depth
can cause elements to be missed; additionally, I have shutdown hooks
that clean up resources and expect the ability to log events and
errors.</div></div>
<div><br></div>
<div>My thought is that a modified AsyncAppenderBase implementation
could (optionally) install a shutdown hook that continues watching the
queue for new events. A configurable "queue idle time" could be used to
tell the shutdown hook that it has probably caught all events and can
safely shutdown (not foolproof, I'm still thinking about other ways of
handling it). Additionally, the hook could have a configurable "max
processing time" so that it doesn't keep the JVM alive for an
undesirable amount of time (thinking in the context of automation
software where shutdown requests typically have a max execution time
before they are considered as "failed online").</div>
<div><br></div>
<div>I hope this helps clarify the scenario I am considering and a
proposed solution!</div>
<div><br></div>
<div>Regards,</div>
<div><br></div>
<div>Mike Reinhold</div></div>
<div class="gmail_extra"><br><br>
<div class="gmail_quote">On Wed, Mar 5, 2014 at 5:30 PM, David Roussel
<span dir="ltr"><<a href="mailto:nabble@diroussel.xsmail.com" target="_blank">nabble@diroussel.xsmail.com</a>></span> wrote:<br>
<blockquote style="BORDER-LEFT:#ccc 1px solid;MARGIN:0px 0px 0px 0.8ex;PADDING-LEFT:1ex" class="gmail_quote">
<div>
<div>Did you try shutting down logback cleanly. Like this <a href="http://stackoverflow.com/questions/3678755/do-i-need-to-flush-events-when-shutting-down-using-logback" target="_blank">http://stackoverflow.com/questions/3678755/do-i-need-to-flush-events-when-shutting-down-using-logback</a><br>
<br>David</div>
<div>
<div>
<div><br>On 5 Mar 2014, at 20:44, Michael Reinhold <<a href="mailto:mike@coursescheduler.io" target="_blank">mike@coursescheduler.io</a>> wrote:<br><br></div>
<blockquote type="cite">
<div>
<div dir="ltr">
<div dir="ltr">
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">Hi
Ceki, </div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">I am
currently using the AsyncAppender in combination with the
LogglyAppender from the Logback extensions project. While working on
a number of aspects of my application, I found that I was not
consistently getting all of the log messages that I expected. In
particular, when the application shuts down immediately (or very
shortly) after a burst of logging activity, the tail of those log
events is often not present in Loggly. From a number of tests, this
issue is not restricted to use with the LogglyAppender, but is
simply more evident because of the latency involved.</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">Looking
through the source code for the AsyncAppenderBase, I saw the
following:</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">You
create the Async sender thread as a Daemon thread</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">addInfo("Setting
discardingThreshold to " + discardingThreshold);</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
worker.setDaemon(true);</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
worker.setName("AsyncAppender-Worker-" +
worker.getName());</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
// make sure this instance is marked as "started" before
staring the worker Thread</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
super.start();</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
worker.start();</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">In the
sender thread, if you determine that the parent thread has stopped
or the async sender thread has been interrupted, you allow the
worker thread to flush remaining log events in the queue.</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">while
(parent.isStarted()) {</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
try {</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
E e = parent.blockingQueue.take();</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
aai.appendLoopOnAppenders(e);</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
} catch (InterruptedException ie) {</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
break;</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
}</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
}</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
addInfo("Worker thread will flush remaining events
before exiting. ");</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
for (E e : parent.blockingQueue) {</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
aai.appendLoopOnAppenders(e);</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
}</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">
aai.detachAndStopAllAppenders();</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">From
what I can tell, during JVM shutdown (for a standalone SE instance,
the same is probably not true for EE instances with application
servers) daemon threads may be terminated without allowing the the
AsyncAppenderBase to escape the while loop and proceed onto the
queue flush for loop. </div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">From
Brian Goetz in Java Concurrency in Practice:</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">"When a
thread exits, the JVM performs an inventory of running threads, and
if the only threads that are left are daemon threads, it initiates
an orderly shutdown. When the JVM halts, any remaining daemon
threads are abandoned finally blocks are not executed, stacks are
not unwound the JVM just exits. Daemon threads should be used
sparingly few processing activities can be safely abandoned at any
time with no cleanup. In particular, it is dangerous to use daemon
threads for tasks that might perform any sort of I/O. Daemon threads
are best saved for "housekeeping" tasks, such as a background thread
that periodically removes expired entries from an in-memory
cache."</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">To test
this, I inserted a break point in the AsyncAppenderBase at the call
to addInfo and ran a variety of different scenarios. At no point in
time was I able to get the breakpoint to stop at the addInfo
line. </div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">I don't
think there are any clear cut solutions to this. Making the worker
thread a user thread instead of daemon thread has its own
implications, particularly that if all other user threads have
exited the async threads would keep the JVM instance alive (unless
System.exit has been called, in which case I believe that you will
still have lost log events even if the async processing thread is
not a daemon). It might be possible to create a shutdown hook that
does the queue flushing for the async worker - though you may need
to consider the possibility of other shutdown hooks wanting to log
events as well.</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">I'm
currently mocking up a version of the AsyncAppenderBase and
AsyncAppender that installs a shutdown hook as described previously.
I think a "queue idle time" configuration might be the best way to
handle other shutdown hooks adding log events (aka - after
processing whatever was in the queue, if no new events are added
within <i><b>x</b></i> ms then the shutdown hook can
assume nothing else will be adding log events and can exit).
An alternative might be to have the shutdown hook query the
ThreadMXBean API to determine if other shutdown hooks are still
executing and possibly adding log events (though the threads that
are expected to be running during shutdown may be not only
application specific but also JVM implementation specific... I'm not
sure).</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">Let me
know what you think. I'll let you know if I feel that my mockup may
be viable...</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">Regards,</div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px"><br></div>
<div style="FONT-FAMILY:arial,sans-serif;FONT-SIZE:13px">Mike
Reinhold</div>
<div><br></div></div></div></div></blockquote></div></div>
<blockquote type="cite">
<div><span>_______________________________________________</span><br><span>Logback-user
mailing list</span><br><span><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a></span><br><span><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a></span></div>
</blockquote></div><br>_______________________________________________<br>Logback-user
mailing list<br><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a><br><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a><br>
</blockquote></div><br></div></div></blockquote>
<blockquote type="cite">
<div><span>_______________________________________________</span><br><span>Logback-user
mailing list</span><br><span><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a></span><br><span><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a></span></div>
</blockquote></div></div></div><br>_______________________________________________<br>Logback-user
mailing list<br><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a><br><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a><br>
</blockquote></div><br></div></div></div><br>_______________________________________________<br>Logback-user
mailing list<br><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a><br><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a><br>
</blockquote></div><br></div></div></div></div></blockquote>
<blockquote type="cite">
<div><span>_______________________________________________</span><br><span>Logback-user
mailing list</span><br><span><a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a></span><br><span><a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a></span></div>
</blockquote></div></div></div></div></div>
<br>_______________________________________________<br>
Logback-user mailing list<br>
<a href="mailto:Logback-user@qos.ch">Logback-user@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a><br></blockquote></div><br></div>