You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by gg...@apache.org on 2015/06/13 22:48:49 UTC
logging-log4j2 git commit: [LOG4J2-982] Use System.nanoTime() to
measure time intervals. Changes to log4j-core only. No changes to
log4j-flume-ng.
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 <ga...@gmail.com>
Authored: Sat Jun 13 13:48:42 2015 -0700
Committer: Gary Gregory <ga...@gmail.com>
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>