You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by mi...@apache.org on 2016/04/18 13:38:07 UTC
[21/50] logging-log4j2 git commit: LOG4J2-1297 made some progress on
latency test
LOG4J2-1297 made some progress on latency test
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/c5f5cc9f
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/c5f5cc9f
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/c5f5cc9f
Branch: refs/heads/LOG4J2-1365
Commit: c5f5cc9f2079235ac36c050bbc42bf3ac28edc28
Parents: 8ebed8f
Author: rpopma <rp...@apache.org>
Authored: Sun Apr 17 22:19:44 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Sun Apr 17 22:19:44 2016 +0900
----------------------------------------------------------------------
.../log4j/core/async/perftest/IdleStrategy.java | 43 ++++++++++
.../core/async/perftest/NoOpIdleStrategy.java | 34 ++++++++
.../core/async/perftest/SimpleLatencyTest.java | 87 +++++++++++++-------
3 files changed, 133 insertions(+), 31 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c5f5cc9f/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/IdleStrategy.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/IdleStrategy.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/IdleStrategy.java
new file mode 100644
index 0000000..77d9d74
--- /dev/null
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/IdleStrategy.java
@@ -0,0 +1,43 @@
+package org.apache.logging.log4j.core.async.perftest;
+
+/**
+ * Idle strategy for use by threads when they do not have work to do.
+ *
+ * <h3>Note regarding implementor state</h3>
+ *
+ * Some implementations are known to be stateful, please note that you cannot safely assume implementations to be stateless.
+ * Where implementations are stateful it is recommended that implementation state is padded to avoid false sharing.
+ *
+ * <h3>Note regarding potential for TTSP(Time To Safe Point) issues</h3>
+ *
+ * If the caller spins in a 'counted' loop, and the implementation does not include a a safepoint poll this may cause a TTSP
+ * (Time To SafePoint) problem. If this is the case for your application you can solve it by preventing the idle method from
+ * being inlined by using a Hotspot compiler command as a JVM argument e.g:
+ * <code>-XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle</code>
+ *
+ * @see <a href="https://github.com/real-logic/Agrona/blob/master/src/main/java/org/agrona/concurrent/IdleStrategy.java">
+ * https://github.com/real-logic/Agrona/blob/master/src/main/java/org/agrona/concurrent/IdleStrategy.java</a>
+ */
+public interface IdleStrategy {
+ /**
+ * Perform current idle action (e.g. nothing/yield/sleep). To be used in conjunction with {@link IdleStrategy#reset()}
+ * to clear internal state when idle period is over (or before it begins). Callers are expected to follow this pattern:
+ *
+ * <pre>
+ * <code>while (isRunning) {
+ * if (!hasWork()) {
+ * idleStrategy.reset();
+ * while (!hasWork()) {
+ * if (!isRunning) {
+ * return;
+ * }
+ * idleStrategy.idle();
+ * }
+ * }
+ * doWork();
+ * }
+ * </code>
+ * </pre>
+ */
+ void idle();
+}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c5f5cc9f/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/NoOpIdleStrategy.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/NoOpIdleStrategy.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/NoOpIdleStrategy.java
new file mode 100644
index 0000000..867a9dd
--- /dev/null
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/NoOpIdleStrategy.java
@@ -0,0 +1,34 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.core.async.perftest;
+
+/**
+ * Low-latency idle strategy to be employed in loops that do significant work on each iteration such that any work in the
+ * idle strategy would be wasteful.
+ */
+public class NoOpIdleStrategy implements IdleStrategy {
+
+ /**
+ * <b>Note</b>: this implementation will result in no safepoint poll once inlined.
+ *
+ * @see IdleStrategy
+ */
+ @Override
+ public void idle() {
+
+ }
+}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c5f5cc9f/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimpleLatencyTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimpleLatencyTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimpleLatencyTest.java
index 93b3621..f7459b6 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimpleLatencyTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimpleLatencyTest.java
@@ -16,15 +16,14 @@
*/
package org.apache.logging.log4j.core.async.perftest;
-import java.lang.management.ManagementFactory;
-import java.lang.management.RuntimeMXBean;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
-import com.lmax.disruptor.collections.Histogram;
+import org.HdrHistogram.Histogram;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.async.AsyncLogger;
-import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector;
/**
*
@@ -33,31 +32,38 @@ public class SimpleLatencyTest {
private static final String LATENCY_MSG = new String(new char[64]);
public static void main(String[] args) throws Exception {
- System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
- System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
- System.setProperty("log4j2.enable.threadlocals", "true");
- System.setProperty("AsyncLogger.WaitStrategy", "Block");
+ //System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
+ //System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
Logger logger = LogManager.getLogger();
- if (!(logger instanceof AsyncLogger)) {
- throw new IllegalStateException();
- }
- logger.info("Starting...");
+ logger.info("Starting..."); // initializes Log4j
Thread.sleep(100);
- System.out.println(PerfTest.calcNanoTimeCost());
final long nanoTimeCost = PerfTest.calcNanoTimeCost();
- final Histogram warmupHistogram = PerfTest.createHistogram();
- final Histogram histogram = PerfTest.createHistogram();
+ System.out.println(nanoTimeCost);
+
+ long maxThroughput = 1000 * 1000; // just assume... TODO make parameter
+ double targetLoadLevel = 0.02; // TODO make parameter
+
+ long targetMsgPerSec = (long) (maxThroughput * targetLoadLevel);
+ long targetMsgCountPerIteration = 5 * 1000 * 1000;
+ long durationMillisPerIteration = (1000 * targetMsgCountPerIteration) / targetMsgPerSec;
+
+
final int threadCount = 1;
+ List<Histogram> warmupHistograms = new ArrayList<>(threadCount);
final int WARMUP_COUNT = 500000;
- runLatencyTest(logger, WARMUP_COUNT, warmupHistogram, nanoTimeCost, threadCount);
+ final long interval = -1; // TODO calculate
+ final IdleStrategy idleStrategy = new NoOpIdleStrategy();
+ runLatencyTest(logger, WARMUP_COUNT, interval, idleStrategy, warmupHistograms, nanoTimeCost, threadCount);
Thread.sleep(1000);
+ List<Histogram> histograms = new ArrayList<>(threadCount);
+
for (int i = 0 ; i < 30; i++) {
final int ITERATIONS = 100 * 1000;// * 30;
- runLatencyTest(logger, ITERATIONS, histogram, nanoTimeCost, threadCount);
+ runLatencyTest(logger, ITERATIONS, interval, idleStrategy, histograms, nanoTimeCost, threadCount);
// wait 10 microsec
final long PAUSE_NANOS = 1000000 * threadCount;
@@ -66,22 +72,41 @@ public class SimpleLatencyTest {
// busy spin
Thread.yield();
}
-
}
-
- System.out.println(histogram);
}
- public static void runLatencyTest(final Logger logger, final int samples, final Histogram histogram,
- final long nanoTimeCost, final int threadCount) {
- for (int i = 0; i < samples; i++) {
- final long s1 = System.nanoTime();
- logger.info(LATENCY_MSG);
- final long s2 = System.nanoTime();
- final long value = s2 - s1 - nanoTimeCost;
- if (value > 0) {
- histogram.addObservation(value);
- }
+ public static void runLatencyTest(final Logger logger, final int samples, final long interval,
+ final IdleStrategy idleStrategy, final List<Histogram> histograms, final long nanoTimeCost,
+ final int threadCount) {
+
+ final CountDownLatch LATCH = new CountDownLatch(threadCount);
+ for (int i = 0; i < threadCount; i++) {
+ final Histogram hist = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
+ histograms.add(hist);
+ final Thread t = new Thread("latencytest-" + i) {
+ public void run() {
+ LATCH.countDown();
+ try {
+ LATCH.await();
+ } catch (InterruptedException e) {
+ interrupt(); // restore interrupt status
+ return;
+ }
+ for (int i = 0; i < samples; i++) {
+ final long s1 = System.nanoTime();
+ logger.info(LATENCY_MSG);
+ final long s2 = System.nanoTime();
+ final long value = s2 - s1 - nanoTimeCost;
+ if (value > 0) {
+ hist.recordValueWithExpectedInterval(value, interval);
+ }
+ while (System.nanoTime() - s2 < interval) {
+ idleStrategy.idle();
+ }
+ }
+ }
+ };
+ t.start();
}
}
}