[
https://issues.apache.org/jira/browse/LOG4J2-2106?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16248908#comment-16248908
]
Remko Popma commented on LOG4J2-2106:
-------------------------------------
Reviewing commit aad2f13:
To be honest, I am not sure why this would solve the issue... Ralph, why do you
think RollingFileManager::checkRollover being synchronized was the cause of the
described latency spikes? Noting that the issue occurs when a rollover is in
progress, and ultimately the thread will need to wait for the rollover to
complete before it can write bytes again, I'm unsure that making the
triggering policy more concurrent will have a dramatic impact. But perhaps I'm
missing something.
About the changes:
*Potential issue 1*
{{RollingFileManager::getFileSize}} (called from both
TimeBasedTriggeringPolicy and SizeBasedTriggeringPolicy) is not a synchronized
method but reads the byteBuffer position which is updated in synchronized
blocks in OutputStreamManager. Should this method be synchronized in
RollingFileManager?
* Would need careful checking to ensure we don't introduce the risk of
deadlock. (I haven't looked in detail yet.)
* This re-introduces a (brief) period where some triggering policies
synchronize on the FileManger. Would this defeat the purpose?
*Potential issue 2*
The manager's PatternProcessor could potentially be modified by two threads
simultaneously if there are two different TriggeringPolicy instances (e.g. a
TimeBasedTriggeringPolicy and a SizeBasedTriggeringPolicy) that both decide the
specified event is a triggering event. Is synchronization on the manager or on
the PatternProcessor required?
*Optimization*
Does {{TimeBasedTriggeringPolicy::isTriggeringEvent}} need to be a
synchronized method? If {{nextRolloverMillis}} is made volatile I think we only
need to synchronize after we decided we may need to return {{true}}...
Something like this:
{code}
private volatile long nextRolloverMillis; // needs to be volatile
public boolean isTriggeringEvent(final LogEvent event) {
final long nowMillis = event.getTimeMillis();
if (nowMillis >= nextRolloverMillis) {
synchronized (this) {
if (manager.getFileSize() == 0) {
return false;
}
nextRolloverMillis = ThreadLocalRandom.current().nextLong(0, 1
+ maxRandomDelayMillis)
+ manager.getPatternProcessor().getNextTime(nowMillis,
interval, modulate);
return true;
}
}
return false;
}
{code}
*Idea for future enhancement*
RollingFileManager::setTriggeringPolicy can be simplified now. Prior to the
introduction of the {{ReadWriteLock updateLock}} field, RollingFileManager
needed to work hard to make changing the TriggeringPolicy lock-free. Given that
this policy rarely changes, a simple lock may be better. Now that
{{setTriggeringPolicy}} is guarded by a write lock, can the lock-free stuff be
removed?
> May blocked when two compress action
> ------------------------------------
>
> Key: LOG4J2-2106
> URL: https://issues.apache.org/jira/browse/LOG4J2-2106
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.9.1
> Reporter: skopt
>
> My log file is very large, so I set the config about compression. The
> policies is as follows:
> <Policies>
> <OnStartupTriggeringPolicy/>
> <TimeBasedTriggeringPolicy/>
> </Policies>
> When restart the service on the hour, this will trigger the two
> policies. And I find that the log can not be written for a while.
> I think, there would be two compress actions. In the file
> RollingFileManager(package org.apache.logging.log4j.core.appender.rolling),
> the actions will submit to asyncExecutor which will create a new thread for
> every work. That mean the log file will be compressed by the two actions. Is
> this the cause?
> Thanks.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
