[
https://issues.apache.org/jira/browse/LOG4J2-1121?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14742543#comment-14742543
]
Remko Popma edited comment on LOG4J2-1121 at 9/13/15 4:55 PM:
--------------------------------------------------------------
I see... So in a reconfiguration scenario, one or more threads had a reference
to the old LoggerConfig, and were invoking one of the log() methods when a new
configuration is swapped in and the old configuration is stopped. Imagine that
the above logging threads were preempted by the OS before they could call the
appender, and the thread that caused the reconfiguration completed executing
stop() on the old configuration before the preempted threads were scheduled to
run again. So the preempted threads will now encounter stopped appenders. Not
good.
Interesting problem. Not sure that the counter/waitForCompletion idea prevents
this problem though (even if AbstractConfiguration.stop() was coded correctly
and clearAppenders() was called before the appenders are stopped): if the
logging thread is suspended after obtaining the reference to the old
LoggerConfig but before it increments the counter, then waitForCompletion has
no idea that this thread exists. The appenders will be cleared and there are no
appenders to log to when the logging thread is scheduled again, so the log
event is lost.
The waitForCompletion() idea makes the window of opportunity for losing an
event smaller, but it cannot prevent it completely.
Perhaps we should consider a different approach. A thread may be preempted at
an unlucky time such that it cannot signal us that it still wants to use the
old configuration. There is nothing we can do about this. So perhaps we should
not try to rely on such signals. What if instead we simply keep the old
configuration around for a while, and only proceed to stop the appenders when
we are reasonably sure that preempted threads have had a chance at being
scheduled and completing their work. Perhaps it is an idea to sleep for some
seconds before calling oldConfiguration.stop()? We could do this in a separate
thread.
was (Author: [email protected]):
I see... So in a reconfiguration scenario, one or more threads had a reference
to the old LoggerConfig, and are invoking one of the log() methods when a new
configuration is swapped in and the old the configuration is stopped. Imagine
that the above threads were preempted by the OS before they could call the
appender, and the thread that caused the reconfiguration completed executing
stop() on the old configuration before the preempted threads were scheduled to
run again. So the preempted threads will now encounter stopped appenders.
Interesting problem. Not sure that the counter/waitForCompletion idea prevents
this problem though (even if AbstractConfiguration.stop() was coded correctly
and clearAppenders() was called before the appenders are stopped): if the
thread is suspended after obtaining the reference to the old LoggerConfig but
before it can increment the counter, then waitForCompletion has no idea that
this thread exists. The appenders will be cleared and there are no appenders to
log to when the logging thread is scheduled again, so the log event is lost.
The waitForCompletion() idea serves to make the window of opportunity for
losing an event smaller, but it cannot prevent it completely.
I think you are right that the way AbstractConfiguration.stop() is coded now it
is possible for a logging thread to encounter a stopped appender.
Perhaps we should consider a different approach. A thread may be preempted at
an unlucky time such that it cannot signal us that it still wants to use the
old configuration. So perhaps we should not try to rely on such signals. What
if instead we keep the old configuration around for a while until we are
reasonably sure that preempted threads have had a chance at being scheduled,
and then proceed to stop the appenders. Perhaps it is an idea to sleep for some
seconds before calling oldConfiguration.stop()? We could do this in a separate
thread.
> LoggerConfig performance improvement: remove waitForCompletion and associated
> fields
> ------------------------------------------------------------------------------------
>
> Key: LOG4J2-1121
> URL: https://issues.apache.org/jira/browse/LOG4J2-1121
> Project: Log4j 2
> Issue Type: Improvement
> Components: Core
> Affects Versions: 2.3
> Reporter: Remko Popma
>
> This ticket follows up on LOG4J2-1120. Out of the three changes identified in
> LOG4J2-1120, only two could be implemented in time for the 2.4 release.
> This ticket tracks the remaining work for the third change:
> * Since {{clearAppenders()}} is only called after all appenders have been
> stopped, {{waitForCompletion()}} may no longer be necessary (unless I am
> missing something here). If so, the {{shutdownLock}}, {{shutdown}} and
> {{counter}} fields can be removed. Not incrementing the atomic counters with
> every event in the hot path should give better performance.
> LOG4J2-1120 shows benchmark results that support this.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
