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 <[email protected]> Authored: Sun Apr 17 22:19:44 2016 +0900 Committer: rpopma <[email protected]> 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(); } } }
