logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (LOG4J2-1121) LoggerConfig performance improvement: remove waitForCompletion and associated fields
Date Sun, 13 Sep 2015 16:55:45 GMT

    [ 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: remkop@yahoo.com):
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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message