Repository: logging-log4j2 Updated Branches: refs/heads/master 4df0d3943 -> b4fe986a3
[LOG4J2-982] Use System.nanoTime() to measure time intervals. Changes to log4j-core only. No changes to log4j-flume-ng. Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/b4fe986a Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/b4fe986a Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/b4fe986a Branch: refs/heads/master Commit: b4fe986a30bf2003a6c8523c5f21e732d1e382a9 Parents: 4df0d39 Author: Gary Gregory <[email protected]> Authored: Sat Jun 13 13:48:42 2015 -0700 Committer: Gary Gregory <[email protected]> Committed: Sat Jun 13 13:48:42 2015 -0700 ---------------------------------------------------------------------- .../core/appender/DefaultErrorHandler.java | 17 +++++++------ .../log4j/core/appender/FailoverAppender.java | 15 +++++------ .../core/config/FileConfigurationMonitor.java | 26 ++++++++++---------- .../logging/log4j/core/FileConfigTest.java | 11 +++++---- .../apache/logging/log4j/core/LoggerTest.java | 7 +++--- .../log4j/core/async/perftest/MtPerfTest.java | 5 ++-- .../log4j/core/async/perftest/PerfTest.java | 5 ++-- .../log4j/core/config/TestConfigurator.java | 2 ++ src/changes/changes.xml | 3 +++ 9 files changed, 51 insertions(+), 40 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/DefaultErrorHandler.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/DefaultErrorHandler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/DefaultErrorHandler.java index 96ec1d1..85e132e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/DefaultErrorHandler.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/DefaultErrorHandler.java @@ -17,6 +17,7 @@ package org.apache.logging.log4j.core.appender; import java.io.Serializable; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.Appender; @@ -35,11 +36,11 @@ public class DefaultErrorHandler implements ErrorHandler, Serializable { private static final int MAX_EXCEPTIONS = 3; - private static final int EXCEPTION_INTERVAL = 300000; + private static final long EXCEPTION_INTERVAL = TimeUnit.MINUTES.toNanos(5); private int exceptionCount = 0; - private long lastException; + private long lastException = System.nanoTime() - EXCEPTION_INTERVAL - 1; private final Appender appender; @@ -54,8 +55,8 @@ public class DefaultErrorHandler implements ErrorHandler, Serializable { */ @Override public void error(final String msg) { - final long current = System.currentTimeMillis(); - if (lastException + EXCEPTION_INTERVAL < current || exceptionCount++ < MAX_EXCEPTIONS) { + final long current = System.nanoTime(); + if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) { LOGGER.error(msg); } lastException = current; @@ -68,8 +69,8 @@ public class DefaultErrorHandler implements ErrorHandler, Serializable { */ @Override public void error(final String msg, final Throwable t) { - final long current = System.currentTimeMillis(); - if (lastException + EXCEPTION_INTERVAL < current || exceptionCount++ < MAX_EXCEPTIONS) { + final long current = System.nanoTime(); + if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) { LOGGER.error(msg, t); } lastException = current; @@ -86,8 +87,8 @@ public class DefaultErrorHandler implements ErrorHandler, Serializable { */ @Override public void error(final String msg, final LogEvent event, final Throwable t) { - final long current = System.currentTimeMillis(); - if (lastException + EXCEPTION_INTERVAL < current || exceptionCount++ < MAX_EXCEPTIONS) { + final long current = System.nanoTime(); + if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) { LOGGER.error(msg, t); } lastException = current; http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/FailoverAppender.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/FailoverAppender.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/FailoverAppender.java index 38e5199..8b6483e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/FailoverAppender.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/FailoverAppender.java @@ -19,6 +19,7 @@ package org.apache.logging.log4j.core.appender; import java.util.ArrayList; import java.util.List; import java.util.Map; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.LoggingException; import org.apache.logging.log4j.core.Appender; @@ -57,9 +58,9 @@ public final class FailoverAppender extends AbstractAppender { private final List<AppenderControl> failoverAppenders = new ArrayList<>(); - private final long intervalMillis; + private final long intervalNanos; - private volatile long nextCheckMillis = 0; + private volatile long nextCheckNanos = 0; private FailoverAppender(final String name, final Filter filter, final String primary, final String[] failovers, final int intervalMillis, final Configuration config, final boolean ignoreExceptions) { @@ -67,7 +68,7 @@ public final class FailoverAppender extends AbstractAppender { this.primaryRef = primary; this.failovers = failovers; this.config = config; - this.intervalMillis = intervalMillis; + this.intervalNanos = TimeUnit.MILLISECONDS.toNanos(intervalMillis); } @@ -107,8 +108,8 @@ public final class FailoverAppender extends AbstractAppender { error("FailoverAppender " + getName() + " did not start successfully"); return; } - final long localCheckMillis = nextCheckMillis; - if (localCheckMillis == 0 || System.currentTimeMillis() > localCheckMillis) { + final long localCheckNanos = nextCheckNanos; + if (localCheckNanos == 0 || System.nanoTime() - localCheckNanos > 0) { callAppender(event); } else { failover(event, null); @@ -118,9 +119,9 @@ public final class FailoverAppender extends AbstractAppender { private void callAppender(final LogEvent event) { try { primary.callAppender(event); - nextCheckMillis = 0; + nextCheckNanos = 0; } catch (final Exception ex) { - nextCheckMillis = System.currentTimeMillis() + intervalMillis; + nextCheckNanos = System.nanoTime() + intervalNanos; failover(event, ex); } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/FileConfigurationMonitor.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/FileConfigurationMonitor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/FileConfigurationMonitor.java index f145696..61d8205 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/FileConfigurationMonitor.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/FileConfigurationMonitor.java @@ -18,6 +18,7 @@ package org.apache.logging.log4j.core.config; import java.io.File; import java.util.List; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReentrantLock; @@ -30,19 +31,17 @@ public class FileConfigurationMonitor implements ConfigurationMonitor { private static final int MASK = 0x0f; - private static final int MIN_INTERVAL = 5; - - private static final int MILLIS_PER_SECOND = 1000; + static final int MIN_INTERVAL = 5; private final File file; - private long lastModified; + private volatile long lastModified; private final List<ConfigurationListener> listeners; - private final int intervalSeconds; + private final long intervalNano; - private long nextCheck; + private volatile long nextCheck; private final AtomicInteger counter = new AtomicInteger(0); @@ -64,8 +63,8 @@ public class FileConfigurationMonitor implements ConfigurationMonitor { this.file = file; this.lastModified = file.lastModified(); this.listeners = listeners; - this.intervalSeconds = (intervalSeconds < MIN_INTERVAL ? MIN_INTERVAL : intervalSeconds) * MILLIS_PER_SECOND; - this.nextCheck = System.currentTimeMillis() + intervalSeconds; + this.intervalNano = TimeUnit.SECONDS.toNanos(Math.max(intervalSeconds, MIN_INTERVAL)); + this.nextCheck = System.nanoTime() + this.intervalNano; } /** @@ -74,12 +73,13 @@ public class FileConfigurationMonitor implements ConfigurationMonitor { @Override public void checkConfiguration() { final long current; - if (((counter.incrementAndGet() & MASK) == 0) && ((current = System.currentTimeMillis()) >= nextCheck)) { + if (((counter.incrementAndGet() & MASK) == 0) && ((current = System.nanoTime()) - nextCheck >= 0)) { LOCK.lock(); try { - nextCheck = current + intervalSeconds; - if (file.lastModified() > lastModified) { - lastModified = file.lastModified(); + nextCheck = current + intervalNano; + final long currentLastModified = file.lastModified(); + if (currentLastModified > lastModified) { + lastModified = currentLastModified; for (final ConfigurationListener listener : listeners) { final Thread thread = new Thread(new ReconfigurationWorker(listener, reconfigurable)); thread.setDaemon(true); @@ -92,7 +92,7 @@ public class FileConfigurationMonitor implements ConfigurationMonitor { } } - private class ReconfigurationWorker implements Runnable { + private static class ReconfigurationWorker implements Runnable { private final ConfigurationListener listener; private final Reconfigurable reconfigurable; http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/test/java/org/apache/logging/log4j/core/FileConfigTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/FileConfigTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/FileConfigTest.java index 840b061..33a0ba6 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/FileConfigTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/FileConfigTest.java @@ -17,8 +17,10 @@ package org.apache.logging.log4j.core; import static org.junit.Assert.assertNotSame; +import static org.junit.Assert.assertTrue; import java.io.File; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.junit.InitialLoggerContext; @@ -46,17 +48,16 @@ public class FileConfigTest { @Test public void testReconfiguration() throws Exception { final Configuration oldConfig = context.getConfiguration(); - final int MONITOR_INTERVAL_SECONDS = 1; + final int MONITOR_INTERVAL_SECONDS = 5; final File file = new File(CONFIG); final long orig = file.lastModified(); final long newTime = orig + 10000; - file.setLastModified(newTime); - final int sleepMillis = (MONITOR_INTERVAL_SECONDS + 1) * 1000; - Thread.sleep(sleepMillis); + assertTrue("setLastModified should have succeeded.", file.setLastModified(newTime)); + TimeUnit.SECONDS.sleep(MONITOR_INTERVAL_SECONDS + 1); for (int i = 0; i < 17; ++i) { logger.debug("Reconfigure"); } - Thread.sleep(sleepMillis); + Thread.sleep(100); final Configuration newConfig = context.getConfiguration(); assertNotSame("Reconfiguration failed", newConfig, oldConfig); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/test/java/org/apache/logging/log4j/core/LoggerTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/LoggerTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/LoggerTest.java index 70f4b70..90c7b41 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/LoggerTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/LoggerTest.java @@ -20,6 +20,7 @@ import java.io.File; import java.util.Date; import java.util.List; import java.util.Locale; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; @@ -197,12 +198,12 @@ public class LoggerTest { @Test public void testReconfiguration() throws Exception { final Configuration oldConfig = context.getConfiguration(); - final int MONITOR_INTERVAL_SECONDS = 1; + final int MONITOR_INTERVAL_SECONDS = 5; final File file = new File("target/test-classes/" + CONFIG); final long orig = file.lastModified(); final long newTime = orig + 10000; - file.setLastModified(newTime); - Thread.sleep((MONITOR_INTERVAL_SECONDS + 1) * 1000); + assertTrue("setLastModified should have succeeded.", file.setLastModified(newTime)); + TimeUnit.SECONDS.sleep(MONITOR_INTERVAL_SECONDS + 1); for (int i = 0; i < 17; ++i) { logger.debug("Reconfigure"); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/MtPerfTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/MtPerfTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/MtPerfTest.java index d01dcb6..c08f4cb 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/MtPerfTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/MtPerfTest.java @@ -17,6 +17,7 @@ package org.apache.logging.log4j.core.async.perftest; import java.io.File; +import java.util.concurrent.TimeUnit; import com.lmax.disruptor.collections.Histogram; @@ -37,14 +38,14 @@ public class MtPerfTest extends PerfTest { // warmup at least 2 rounds and at most 1 minute final Histogram warmupHist = PerfTest.createHistogram(); - final long stop = System.currentTimeMillis() + (60 * 1000); + final long stop = System.nanoTime() + TimeUnit.MINUTES.toNanos(1); final Runnable run1 = new Runnable() { @Override public void run() { for (int i = 0; i < 10; i++) { final int LINES = PerfTest.throughput ? 50000 : 200000; runTest(runner, LINES, null, warmupHist, 2); - if (i > 0 && System.currentTimeMillis() >= stop) { + if (i > 0 && System.nanoTime() - stop >= 0) { return; } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java index c792db5..463c020 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java @@ -20,6 +20,7 @@ import java.io.FileWriter; import java.io.IOException; import java.nio.charset.Charset; import java.util.Arrays; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.core.util.Loader; @@ -108,11 +109,11 @@ public class PerfTest { // warmup at least 10 seconds final int LINES = 50000; int iterations = 0; - final long stop = System.currentTimeMillis() + (10 * 1000); // 10 seconds + final long stop = System.nanoTime() + TimeUnit.SECONDS.toNanos(10); do { runTest(runner, LINES, null, warmupHist, 1); iterations++; - } while (System.currentTimeMillis() < stop); + } while (System.nanoTime() - stop < 0); printf("Warmup complete in %.1f seconds (%d iterations)%n", (System.nanoTime() - t1) / (1000.0 * 1000.0 * 1000.0), iterations); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/log4j-core/src/test/java/org/apache/logging/log4j/core/config/TestConfigurator.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/config/TestConfigurator.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/config/TestConfigurator.java index 52e4055..0f87ff6 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/config/TestConfigurator.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/config/TestConfigurator.java @@ -21,6 +21,7 @@ import java.io.FileInputStream; import java.io.InputStream; import java.io.Serializable; import java.util.Map; +import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; @@ -240,6 +241,7 @@ public class TestConfigurator { Thread.sleep(500); } assertTrue("setLastModified should have succeeded.", file.setLastModified(System.currentTimeMillis())); + TimeUnit.SECONDS.sleep(FileConfigurationMonitor.MIN_INTERVAL + 1); for (int i = 0; i < 17; ++i) { logger.debug("Test message " + i); } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/b4fe986a/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index 4ab4ecf..7f9aca8 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -72,6 +72,9 @@ <action issue="LOG4J2-1046" dev="ggregory" type="fix" due-to="Kenneth Gendron"> Circular Exception cause throws StackOverflowError. </action> + <action issue="LOG4J2-982" dev="ggregory" type="fix" due-to="Mikhail Mazurskiy"> + Use System.nanoTime() to measure time intervals. + </action> <action issue="LOG4J2-890" dev="ggregory" type="update" due-to="Hassan Kalaldeh, Robert Andersson, Remko Popma"> log4j-web-2.1 should workaround a bug in JBOSS EAP 6.2. </action>
