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/05/07 15:35:24 UTC
logging-log4j2 git commit: LOG4J2-1297 instantiate new Pacer for each
call to runLatencyTest() as Gil suggested;
generalize to allow testing other logging frameworks
Repository: logging-log4j2
Updated Branches:
refs/heads/master 2cd922b61 -> 0754292b6
LOG4J2-1297 instantiate new Pacer for each call to runLatencyTest() as Gil suggested; generalize to allow testing other logging frameworks
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/0754292b
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/0754292b
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/0754292b
Branch: refs/heads/master
Commit: 0754292b605431810fbac2ab0231af25c2782a9e
Parents: 2cd922b
Author: rpopma <rp...@apache.org>
Authored: Sun May 8 00:35:42 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Sun May 8 00:35:42 2016 +0900
----------------------------------------------------------------------
.../core/async/perftest/ResponseTimeTest.java | 97 ++++++++++----------
1 file changed, 49 insertions(+), 48 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/0754292b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
index 7f01cdf..296d4b4 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
@@ -16,14 +16,6 @@
*/
package org.apache.logging.log4j.core.async.perftest;
-import org.HdrHistogram.Histogram;
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.async.DefaultAsyncEventRouter;
-import org.apache.logging.log4j.core.async.EventRoute;
-import org.apache.logging.log4j.core.util.Constants;
-
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.PrintStream;
@@ -31,6 +23,14 @@ import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+
+import org.HdrHistogram.Histogram;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.async.DefaultAsyncEventRouter;
+import org.apache.logging.log4j.core.async.EventRoute;
+import org.apache.logging.log4j.core.util.Constants;
+import org.apache.logging.log4j.core.util.Loader;
/**
* Latency test showing both service time and response time.
@@ -52,23 +52,31 @@ public class ResponseTimeTest {
public static void main(String[] args) throws Exception {
if (args.length < 2) {
- System.out.println("Please specify thread count and target throughput (msg/sec)");
+ System.out.println("Please specify thread count, target throughput (msg/sec) " +
+ "and logger library (Log4j1, Log4j2, Logback, JUL)");
return;
}
final int threadCount = Integer.parseInt(args[0]);
final double loadMessagesPerSec = Double.parseDouble(args[1]);
+ final String loggerLib = args.length > 2 ? args[2] : "Log4j2";
// print to console if ringbuffer is full
System.setProperty("log4j2.AsyncEventRouter", PrintingDefaultAsyncEventRouter.class.getName());
System.setProperty("AsyncLogger.RingBufferSize", String.valueOf(256 * 1024));
//System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
- System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
+ //System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
if (System.getProperty("AsyncLogger.WaitStrategy") == null) {
System.setProperty("AsyncLogger.WaitStrategy", "Yield");
}
-
- Logger logger = LogManager.getLogger();
- logger.info("Starting..."); // initializes Log4j
+ //for (Object key : System.getProperties().keySet()) {
+ // System.out.println(key + "=" + System.getProperty((String) key));
+ //}
+
+ // initialize the logger
+ final String wrapper = loggerLib.startsWith("Run") ? loggerLib : "Run" + loggerLib;
+ final String loggerWrapperClass = "org.apache.logging.log4j.core.async.perftest." + wrapper;
+ final IPerfTestRunner logger = Loader.newCheckedInstanceOf(loggerWrapperClass, IPerfTestRunner.class);
+ logger.log("Starting..."); // ensure initialized
Thread.sleep(100);
final int requiredProcessors = threadCount + 1 + 1; // producers + 1 consumer + 1 for OS
@@ -76,8 +84,8 @@ public class ResponseTimeTest {
? new NoOpIdleStrategy()
: new YieldIdleStrategy();
- System.out.printf("%d threads, load is %,f msg/sec, using %s%n", threadCount, loadMessagesPerSec,
- idleStrategy.getClass().getSimpleName());
+ System.out.printf("%s: %d threads, load is %,f msg/sec, using %s%n", loggerLib, threadCount,
+ loadMessagesPerSec, idleStrategy.getClass().getSimpleName());
// Warmup: run as many iterations of 50,000 calls to logger.log as we can in 1 minute
final long WARMUP_DURATION_MILLIS = TimeUnit.MINUTES.toMillis(1);
@@ -85,32 +93,25 @@ public class ResponseTimeTest {
List<Histogram> warmupResponseTmHistograms = new ArrayList<>(threadCount);
final int WARMUP_COUNT = 50000 / threadCount;
- final CountDownLatch warmupLatch = new CountDownLatch(threadCount + 1);
- Thread[] warmup = createLatencyTest(logger, WARMUP_DURATION_MILLIS, WARMUP_COUNT, warmupLatch, loadMessagesPerSec,
- idleStrategy, warmupServiceTmHistograms, warmupResponseTmHistograms, threadCount);
+ runLatencyTest(logger, WARMUP_DURATION_MILLIS, WARMUP_COUNT, loadMessagesPerSec, idleStrategy,
+ warmupServiceTmHistograms, warmupResponseTmHistograms, threadCount);
+ System.out.println("-----------------Warmup done. load=" + loadMessagesPerSec);
+ if (!Constants.ENABLE_DIRECT_ENCODERS || !Constants.ENABLE_THREADLOCALS) {
+ //System.gc();
+ //Thread.sleep(5000);
+ }
+ System.out.println("-----------------Starting measured run. load=" + loadMessagesPerSec);
+ long start = System.currentTimeMillis();
List<Histogram> serviceTmHistograms = new ArrayList<>(threadCount);
List<Histogram> responseTmHistograms = new ArrayList<>(threadCount);
+ PrintingDefaultAsyncEventRouter.ringbufferFull.set(0);
+ // Actual test: run as many iterations of 1,000,000 calls to logger.log as we can in 4 minutes.
final long TEST_DURATION_MILLIS = TimeUnit.MINUTES.toMillis(4);
final int COUNT = (1000 * 1000) / threadCount;
- final CountDownLatch actualLatch = new CountDownLatch(threadCount + 1);
- Thread[] actual = createLatencyTest(logger, TEST_DURATION_MILLIS, COUNT, actualLatch, loadMessagesPerSec, idleStrategy,
- serviceTmHistograms, responseTmHistograms, threadCount);
-
- warmupLatch.countDown();
- await(warmup);
- System.out.println("Warmup done.");
- if (!Constants.ENABLE_DIRECT_ENCODERS || !Constants.ENABLE_THREADLOCALS) {
- System.gc();
- Thread.sleep(5000);
- }
- System.out.println("Starting measured run.");
-
- // Actual test: run as many iterations of 5,000,000 calls to logger.log as we can in 4 minutes.
- long start = System.currentTimeMillis();
- actualLatch.countDown(); // start the actual test threads
- await(actual);
+ runLatencyTest(logger, TEST_DURATION_MILLIS, COUNT, loadMessagesPerSec, idleStrategy, serviceTmHistograms,
+ responseTmHistograms, threadCount);
long end = System.currentTimeMillis();
// ... and report the results
@@ -122,6 +123,8 @@ public class ResponseTimeTest {
resultResponseTm.outputPercentileDistribution(System.out, 1000.0);
writeToFile("r", resultResponseTm, (int) (loadMessagesPerSec / 1000), 1000.0);
+ System.out.printf("%n%s: %d threads, load %,f msg/sec, ringbuffer full=%d%n", loggerLib, threadCount,
+ loadMessagesPerSec, PrintingDefaultAsyncEventRouter.ringbufferFull.get());
System.out.println("Test duration: " + (end - start) / 1000.0 + " seconds");
}
@@ -142,55 +145,51 @@ public class ResponseTimeTest {
return result;
}
- public static Thread[] createLatencyTest(final Logger logger, final long durationMillis, final int samples,
- final CountDownLatch latch, final double loadMessagesPerSec, final IdleStrategy idleStrategy,
+ public static void runLatencyTest(final IPerfTestRunner logger, final long durationMillis, final int samples,
+ final double loadMessagesPerSec, final IdleStrategy idleStrategy,
final List<Histogram> serviceTmHistograms, final List<Histogram> responseTmHistograms,
final int threadCount) throws InterruptedException {
final Thread[] threads = new Thread[threadCount];
+ final CountDownLatch LATCH = new CountDownLatch(threadCount);
for (int i = 0; i < threadCount; i++) {
final Histogram serviceTmHist = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
final Histogram responseTmHist = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
serviceTmHistograms.add(serviceTmHist);
responseTmHistograms.add(responseTmHist);
- final Pacer pacer = new Pacer(loadMessagesPerSec, idleStrategy);
threads[i] = new Thread("latencytest-" + i) {
@Override
public void run() {
- latch.countDown();
+ LATCH.countDown();
try {
- latch.await(); // wait until all threads are ready to go
+ LATCH.await(); // wait until all threads are ready to go
} catch (InterruptedException e) {
interrupt();
return;
}
final long endTimeMillis = System.currentTimeMillis() + durationMillis;
do {
+ final Pacer pacer = new Pacer(loadMessagesPerSec, idleStrategy);
runLatencyTest(samples, logger, serviceTmHist, responseTmHist, pacer);
} while (System.currentTimeMillis() < endTimeMillis);
}
};
threads[i].start();
}
- return threads;
- }
-
- private static void await(final Thread[] threads) throws InterruptedException {
- for (int i = 0; i < threads.length; i++) {
+ for (int i = 0; i < threadCount; i++) {
threads[i].join();
}
}
- private static void runLatencyTest(final int samples, final Logger logger, final Histogram serviceTmHist,
+ private static void runLatencyTest(final int samples, final IPerfTestRunner logger, final Histogram serviceTmHist,
final Histogram responseTmHist, final Pacer pacer) {
- pacer.setInitialStartTime(System.nanoTime());
for (int i = 0; i < samples; i++) {
final long expectedStartTimeNanos = pacer.expectedNextOperationNanoTime();
pacer.acquire(1);
final long actualStartTime = System.nanoTime();
- logger.info(LATENCY_MSG);
+ logger.log(LATENCY_MSG);
final long doneTime = System.nanoTime();
serviceTmHist.recordValue(doneTime - actualStartTime);
responseTmHist.recordValue(doneTime - expectedStartTimeNanos);
@@ -198,8 +197,10 @@ public class ResponseTimeTest {
}
public static class PrintingDefaultAsyncEventRouter extends DefaultAsyncEventRouter {
+ static AtomicLong ringbufferFull = new AtomicLong();
@Override
public EventRoute getRoute(long backgroundThreadId, Level level) {
+ ringbufferFull.incrementAndGet();
System.out.print('!');
return super.getRoute(backgroundThreadId, level);
}