You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2016/04/18 16:04:27 UTC
logging-log4j2 git commit: LOG4J2-1297 latency test update
Repository: logging-log4j2
Updated Branches:
refs/heads/master ea6e1808b -> 45a856dc9
LOG4J2-1297 latency test update
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/45a856dc
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/45a856dc
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/45a856dc
Branch: refs/heads/master
Commit: 45a856dc9a16e11cd76774a0f94ea80f328241e9
Parents: ea6e180
Author: rpopma <rp...@apache.org>
Authored: Mon Apr 18 23:04:33 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Mon Apr 18 23:04:33 2016 +0900
----------------------------------------------------------------------
.../log4j/core/async/perftest/IdleStrategy.java | 18 ++++-
.../core/async/perftest/NoOpIdleStrategy.java | 2 +-
.../core/async/perftest/SimpleLatencyTest.java | 80 ++++++++++++--------
3 files changed, 66 insertions(+), 34 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/45a856dc/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
index 77d9d74..eca115c 100644
--- 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
@@ -1,3 +1,19 @@
+/*
+ * 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;
/**
@@ -18,7 +34,7 @@ package org.apache.logging.log4j.core.async.perftest;
* @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 {
+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:
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/45a856dc/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
index 867a9dd..ad5d280 100644
--- 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
@@ -20,7 +20,7 @@ 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 {
+class NoOpIdleStrategy implements IdleStrategy {
/**
* <b>Note</b>: this implementation will result in no safepoint poll once inlined.
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/45a856dc/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 90341ad..5379a46 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
@@ -24,6 +24,7 @@ import java.util.concurrent.TimeUnit;
import org.HdrHistogram.Histogram;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector;
/**
* Latency test.
@@ -59,8 +60,8 @@ 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("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
+ System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
Logger logger = LogManager.getLogger();
logger.info("Starting..."); // initializes Log4j
@@ -69,48 +70,60 @@ public class SimpleLatencyTest {
final long nanoTimeCost = PerfTest.calcNanoTimeCost();
System.out.println(nanoTimeCost);
- long maxThroughput = 1000 * 1000; // just assume... TODO make parameter
- double targetLoadLevel = 0.02; // TODO make parameter
+ long maxOpsPerSec = 1000 * 1000; // just assume... TODO make parameter
+ double targetLoadLevel = 0.05; // TODO make parameter
- long targetMsgPerSec = (long) (maxThroughput * targetLoadLevel);
- long targetMsgCountPerIteration = 5 * 1000 * 1000;
- long durationMillisPerIteration = (1000 * targetMsgCountPerIteration) / targetMsgPerSec;
+ long oneOpDurationNanos = TimeUnit.SECONDS.toNanos(1) / maxOpsPerSec;
+ long idleTimeNanos = (long) ((1.0 - targetLoadLevel) * oneOpDurationNanos);
+ System.out.printf("Idle time is %d nanos at %,f load level%n", idleTimeNanos, targetLoadLevel);
+ final int WARMUP_ITERATIONS = 5;
+ final int threadCount = 8;
+ List<List<Histogram>> warmups = new ArrayList<>();
+ for (int i = 0; i < WARMUP_ITERATIONS; i++) {
+ List<Histogram> warmupHistograms = new ArrayList<>(threadCount);
- final int threadCount = 1;
- List<Histogram> warmupHistograms = new ArrayList<>(threadCount);
-
- final int WARMUP_COUNT = 500000;
- 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);
+ final int WARMUP_COUNT = 500000;
+ final long interval = idleTimeNanos;
+ final IdleStrategy idleStrategy = new NoOpIdleStrategy();
+ runLatencyTest(logger, WARMUP_COUNT, interval, idleStrategy, warmupHistograms, nanoTimeCost, threadCount);
+ warmups.add(warmupHistograms);
+ }
- for (int i = 0; i < 30; i++) {
- final int ITERATIONS = 100 * 1000;// * 30;
- runLatencyTest(logger, ITERATIONS, interval, idleStrategy, histograms, nanoTimeCost, threadCount);
+ long start = System.currentTimeMillis();
+ final int MEASURED_ITERATIONS = 5;
+ List<List<Histogram>> tests = new ArrayList<>();
+ for (int i = 0; i < MEASURED_ITERATIONS; i++) {
+ List<Histogram> histograms = new ArrayList<>(threadCount);
+
+ final int COUNT = 5000000;
+ final long interval = idleTimeNanos;
+ final IdleStrategy idleStrategy = new NoOpIdleStrategy();
+ runLatencyTest(logger, COUNT, interval, idleStrategy, histograms, nanoTimeCost, threadCount);
+ tests.add(histograms);
+ }
+ long end = System.currentTimeMillis();
- // wait 10 microsec
- final long PAUSE_NANOS = 1000000 * threadCount;
- final long pauseStart = System.nanoTime();
- while (PAUSE_NANOS > (System.nanoTime() - pauseStart)) {
- // busy spin
- Thread.yield();
+ final Histogram result = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
+ for (List<Histogram> done : tests) {
+ for (Histogram hist : done) {
+ result.add(hist);
}
}
+ result.outputPercentileDistribution(System.out, 1000.0);
+ System.out.println("Test duration: " + (end - start) / 1000.0 + " seconds");
}
- public static void runLatencyTest(final Logger logger, final int samples, final long interval,
+ public static void runLatencyTest(final Logger logger, final int samples, final long intervalNanos,
final IdleStrategy idleStrategy, final List<Histogram> histograms, final long nanoTimeCost,
- final int threadCount) {
+ final int threadCount) throws InterruptedException {
+ Thread[] threads = new Thread[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) {
+ threads[i] = new Thread("latencytest-" + i) {
@Override
public void run() {
LATCH.countDown();
@@ -126,15 +139,18 @@ public class SimpleLatencyTest {
final long s2 = System.nanoTime();
final long value = s2 - s1 - nanoTimeCost;
if (value > 0) {
- hist.recordValueWithExpectedInterval(value, interval);
+ hist.recordValueWithExpectedInterval(value, intervalNanos);
}
- while (System.nanoTime() - s2 < interval) {
+ while (System.nanoTime() - s2 < intervalNanos) {
idleStrategy.idle();
}
}
}
};
- t.start();
+ threads[i].start();
+ }
+ for (int i = 0; i < threadCount; i++) {
+ threads[i].join();
}
}
}