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 <[email protected]> Authored: Sun May 8 00:35:42 2016 +0900 Committer: rpopma <[email protected]> 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); }
