Return-Path: X-Original-To: apmail-logging-commits-archive@minotaur.apache.org Delivered-To: apmail-logging-commits-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 22B6E10A58 for ; Fri, 16 Aug 2013 03:34:22 +0000 (UTC) Received: (qmail 80024 invoked by uid 500); 16 Aug 2013 03:34:22 -0000 Delivered-To: apmail-logging-commits-archive@logging.apache.org Received: (qmail 79998 invoked by uid 500); 16 Aug 2013 03:34:21 -0000 Mailing-List: contact commits-help@logging.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@logging.apache.org Delivered-To: mailing list commits@logging.apache.org Received: (qmail 79988 invoked by uid 99); 16 Aug 2013 03:34:20 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 16 Aug 2013 03:34:20 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.4] (HELO eris.apache.org) (140.211.11.4) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 16 Aug 2013 03:34:15 +0000 Received: from eris.apache.org (localhost [127.0.0.1]) by eris.apache.org (Postfix) with ESMTP id 3288123888E7; Fri, 16 Aug 2013 03:33:53 +0000 (UTC) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r1514565 - in /logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest: MTPerfTest.java PerfTest.java PerfTestResultFormatter.java RunLogback.java Date: Fri, 16 Aug 2013 03:33:52 -0000 To: commits@logging.apache.org From: rpopma@apache.org X-Mailer: svnmailer-1.0.9 Message-Id: <20130816033353.3288123888E7@eris.apache.org> X-Virus-Checked: Checked by ClamAV on apache.org Author: rpopma Date: Fri Aug 16 03:33:52 2013 New Revision: 1514565 URL: http://svn.apache.org/r1514565 Log: replacing tab indents with spaces (Pot. Kettle... ahem) Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/MTPerfTest.java logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestResultFormatter.java logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/RunLogback.java Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/MTPerfTest.java URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/MTPerfTest.java?rev=1514565&r1=1514564&r2=1514565&view=diff ============================================================================== --- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/MTPerfTest.java (original) +++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/MTPerfTest.java Fri Aug 16 03:33:52 2013 @@ -22,90 +22,90 @@ import com.lmax.disruptor.collections.Hi public class MTPerfTest extends PerfTest { - public static void main(final String[] args) throws Exception { - new MTPerfTest().doMain(args); - } - - @Override - public void runTestAndPrintResult(final IPerfTestRunner runner, - final String name, final int threadCount, final String resultFile) - throws Exception { - - // ThreadContext.put("aKey", "mdcVal"); - PerfTest.println("Warming up the JVM..."); - final long t1 = System.nanoTime(); - - // warmup at least 2 rounds and at most 1 minute - final Histogram warmupHist = PerfTest.createHistogram(); - final long stop = System.currentTimeMillis() + (60 * 1000); - final Runnable run1 = new Runnable() { - @Override + public static void main(final String[] args) throws Exception { + new MTPerfTest().doMain(args); + } + + @Override + public void runTestAndPrintResult(final IPerfTestRunner runner, + final String name, final int threadCount, final String resultFile) + throws Exception { + + // ThreadContext.put("aKey", "mdcVal"); + PerfTest.println("Warming up the JVM..."); + final long t1 = System.nanoTime(); + + // warmup at least 2 rounds and at most 1 minute + final Histogram warmupHist = PerfTest.createHistogram(); + final long stop = System.currentTimeMillis() + (60 * 1000); + final Runnable run1 = new Runnable() { + @Override public void run() { - for (int i = 0; i < 10; i++) { - final int LINES = PerfTest.throughput ? 50000 : 200000; - runTest(runner, LINES, null, warmupHist, 2); - if (i > 0 && System.currentTimeMillis() >= stop) { - return; - } - } - } - }; - final Thread thread1 = new Thread(run1); - final Thread thread2 = new Thread(run1); - thread1.start(); - thread2.start(); - thread1.join(); - thread2.join(); - - PerfTest.printf("Warmup complete in %.1f seconds%n", - (System.nanoTime() - t1) / (1000.0 * 1000.0 * 1000.0)); - PerfTest.println("Waiting 10 seconds for buffers to drain warmup data..."); - Thread.sleep(10000); - new File("perftest.log").delete(); - new File("perftest.log").createNewFile(); - - PerfTest.println("Starting the main test..."); - PerfTest.throughput = false; - multiThreadedTestRun(runner, name, threadCount, resultFile); - - Thread.sleep(1000); - PerfTest.throughput = true; - multiThreadedTestRun(runner, name, threadCount, resultFile); - } - - private void multiThreadedTestRun(final IPerfTestRunner runner, - final String name, final int threadCount, final String resultFile) - throws Exception { - - final Histogram[] histograms = new Histogram[threadCount]; - for (int i = 0; i < histograms.length; i++) { - histograms[i] = PerfTest.createHistogram(); - } - final int LINES = 256 * 1024; - - final Thread[] threads = new Thread[threadCount]; - for (int i = 0; i < threads.length; i++) { - final Histogram histogram = histograms[i]; - threads[i] = new Thread() { - @Override + for (int i = 0; i < 10; i++) { + final int LINES = PerfTest.throughput ? 50000 : 200000; + runTest(runner, LINES, null, warmupHist, 2); + if (i > 0 && System.currentTimeMillis() >= stop) { + return; + } + } + } + }; + final Thread thread1 = new Thread(run1); + final Thread thread2 = new Thread(run1); + thread1.start(); + thread2.start(); + thread1.join(); + thread2.join(); + + PerfTest.printf("Warmup complete in %.1f seconds%n", + (System.nanoTime() - t1) / (1000.0 * 1000.0 * 1000.0)); + PerfTest.println("Waiting 10 seconds for buffers to drain warmup data..."); + Thread.sleep(10000); + new File("perftest.log").delete(); + new File("perftest.log").createNewFile(); + + PerfTest.println("Starting the main test..."); + PerfTest.throughput = false; + multiThreadedTestRun(runner, name, threadCount, resultFile); + + Thread.sleep(1000); + PerfTest.throughput = true; + multiThreadedTestRun(runner, name, threadCount, resultFile); + } + + private void multiThreadedTestRun(final IPerfTestRunner runner, + final String name, final int threadCount, final String resultFile) + throws Exception { + + final Histogram[] histograms = new Histogram[threadCount]; + for (int i = 0; i < histograms.length; i++) { + histograms[i] = PerfTest.createHistogram(); + } + final int LINES = 256 * 1024; + + final Thread[] threads = new Thread[threadCount]; + for (int i = 0; i < threads.length; i++) { + final Histogram histogram = histograms[i]; + threads[i] = new Thread() { + @Override public void run() { -// int latencyCount = threadCount >= 16 ? 1000000 : 5000000; - final int latencyCount = 5000000; - final int count = PerfTest.throughput ? LINES / threadCount - : latencyCount; - runTest(runner, count, "end", histogram, threadCount); - } - }; - } - for (final Thread thread : threads) { - thread.start(); - } - for (final Thread thread : threads) { - thread.join(); - } - - for (final Histogram histogram : histograms) { - PerfTest.reportResult(resultFile, name, histogram); - } - } +// int latencyCount = threadCount >= 16 ? 1000000 : 5000000; + final int latencyCount = 5000000; + final int count = PerfTest.throughput ? LINES / threadCount + : latencyCount; + runTest(runner, count, "end", histogram, threadCount); + } + }; + } + for (final Thread thread : threads) { + thread.start(); + } + for (final Thread thread : threads) { + thread.join(); + } + + for (final Histogram histogram : histograms) { + PerfTest.reportResult(resultFile, name, histogram); + } +} } \ No newline at end of file Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java?rev=1514565&r1=1514564&r2=1514565&view=diff ============================================================================== --- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java (original) +++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTest.java Fri Aug 16 03:33:52 2013 @@ -23,165 +23,165 @@ import com.lmax.disruptor.collections.Hi public class PerfTest { - private static final String LINE100 = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890!\"#$%&'()-=^~|\\@`[]{};:+*,.<>/?_123456"; - public static final String LINE500 = LINE100 + LINE100 + LINE100 + LINE100 - + LINE100; - - static boolean verbose = false; - static boolean throughput; - - // determine how long it takes to call System.nanoTime() (on average) - static long calcNanoTimeCost() { - final long iterations = 10000000; - final long start = System.nanoTime(); - long finish = start; - - for (int i = 0; i < iterations; i++) { - finish = System.nanoTime(); - } - - if (finish <= start) { - throw new IllegalStateException(); - } - - finish = System.nanoTime(); - return (finish - start) / iterations; - } - - static Histogram createHistogram() { - final long[] intervals = new long[31]; - long intervalUpperBound = 1L; - for (int i = 0, size = intervals.length - 1; i < size; i++) { - intervalUpperBound *= 2; - intervals[i] = intervalUpperBound; - } - - intervals[intervals.length - 1] = Long.MAX_VALUE; - return new Histogram(intervals); - } - - public static void main(final String[] args) throws Exception { - new PerfTest().doMain(args); - } - - public void doMain(final String[] args) throws Exception { - final String runnerClass = args[0]; - final IPerfTestRunner runner = (IPerfTestRunner) Class.forName(runnerClass) - .newInstance(); - final String name = args[1]; - final String resultFile = args.length > 2 ? args[2] : null; - for (final String arg : args) { - if (verbose && throughput) { - break; - } - if ("-verbose".equalsIgnoreCase(arg)) { - verbose = true; - } - if ("-throughput".equalsIgnoreCase(arg)) { - throughput = true; - } - } - final int threadCount = args.length > 2 ? Integer.parseInt(args[3]) : 3; - printf("Starting %s %s (%d)...%n", getClass().getSimpleName(), name, - threadCount); - runTestAndPrintResult(runner, name, threadCount, resultFile); - runner.shutdown(); - System.exit(0); - } - - public void runTestAndPrintResult(final IPerfTestRunner runner, - final String name, final int threadCount, final String resultFile) - throws Exception { - final Histogram warmupHist = createHistogram(); - - // ThreadContext.put("aKey", "mdcVal"); - println("Warming up the JVM..."); - final long t1 = System.nanoTime(); - - // warmup at least 2 rounds and at most 1 minute - final long stop = System.currentTimeMillis() + (60 * 1000); - for (int i = 0; i < 10; i++) { - final int LINES = throughput ? 50000 : 200000; - runTest(runner, LINES, null, warmupHist, 1); - if (i > 0 && System.currentTimeMillis() >= stop) { - return; - } - } - - printf("Warmup complete in %.1f seconds%n", (System.nanoTime() - t1) - / (1000.0 * 1000.0 * 1000.0)); - println("Waiting 10 seconds for buffers to drain warmup data..."); - Thread.sleep(10000); - - println("Starting the main test..."); - // test - throughput = false; - runSingleThreadedTest(runner, name, resultFile); - - Thread.sleep(1000); - - throughput = true; - runSingleThreadedTest(runner, name, resultFile); - } - - private int runSingleThreadedTest(final IPerfTestRunner runner, final String name, - final String resultFile) throws IOException { - final Histogram latency = createHistogram(); - final int LINES = throughput ? 50000 : 5000000; - runTest(runner, LINES, "end", latency, 1); - reportResult(resultFile, name, latency); - return LINES; - } - - static void reportResult(final String file, final String name, final Histogram histogram) - throws IOException { - final String result = createSamplingReport(name, histogram); - println(result); - - if (file != null) { - final FileWriter writer = new FileWriter(file, true); - writer.write(result); - writer.write(System.getProperty("line.separator")); - writer.close(); - } - } - - static void printf(final String msg, final Object... objects) { - if (verbose) { - System.out.printf(msg, objects); - } - } - - static void println(final String msg) { - if (verbose) { - System.out.println(msg); - } - } - - static String createSamplingReport(final String name, final Histogram histogram) { - final Histogram data = histogram; - if (throughput) { - return data.getMax() + " operations/second"; - } - final String result = String.format( - "avg=%.0f 99%%=%d 99.99%%=%d sampleCount=%d", data.getMean(), // - data.getTwoNinesUpperBound(), // - data.getFourNinesUpperBound(), // - data.getCount() // - ); - return result; - } - - public void runTest(final IPerfTestRunner runner, final int lines, final String finalMessage, - final Histogram histogram, final int threadCount) { - if (throughput) { - runner.runThroughputTest(lines, histogram); - } else { - final long nanoTimeCost = calcNanoTimeCost(); - runner.runLatencyTest(lines, histogram, nanoTimeCost, threadCount); - } - if (finalMessage != null) { - runner.log(finalMessage); - } - } + private static final String LINE100 = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz1234567890!\"#$%&'()-=^~|\\@`[]{};:+*,.<>/?_123456"; + public static final String LINE500 = LINE100 + LINE100 + LINE100 + LINE100 + + LINE100; + + static boolean verbose = false; + static boolean throughput; + + // determine how long it takes to call System.nanoTime() (on average) + static long calcNanoTimeCost() { + final long iterations = 10000000; + final long start = System.nanoTime(); + long finish = start; + + for (int i = 0; i < iterations; i++) { + finish = System.nanoTime(); + } + + if (finish <= start) { + throw new IllegalStateException(); + } + + finish = System.nanoTime(); + return (finish - start) / iterations; + } + + static Histogram createHistogram() { + final long[] intervals = new long[31]; + long intervalUpperBound = 1L; + for (int i = 0, size = intervals.length - 1; i < size; i++) { + intervalUpperBound *= 2; + intervals[i] = intervalUpperBound; + } + + intervals[intervals.length - 1] = Long.MAX_VALUE; + return new Histogram(intervals); + } + + public static void main(final String[] args) throws Exception { + new PerfTest().doMain(args); + } + + public void doMain(final String[] args) throws Exception { + final String runnerClass = args[0]; + final IPerfTestRunner runner = (IPerfTestRunner) Class.forName(runnerClass) + .newInstance(); + final String name = args[1]; + final String resultFile = args.length > 2 ? args[2] : null; + for (final String arg : args) { + if (verbose && throughput) { + break; + } + if ("-verbose".equalsIgnoreCase(arg)) { + verbose = true; + } + if ("-throughput".equalsIgnoreCase(arg)) { + throughput = true; + } + } + final int threadCount = args.length > 2 ? Integer.parseInt(args[3]) : 3; + printf("Starting %s %s (%d)...%n", getClass().getSimpleName(), name, + threadCount); + runTestAndPrintResult(runner, name, threadCount, resultFile); + runner.shutdown(); + System.exit(0); + } + + public void runTestAndPrintResult(final IPerfTestRunner runner, + final String name, final int threadCount, final String resultFile) + throws Exception { + final Histogram warmupHist = createHistogram(); + + // ThreadContext.put("aKey", "mdcVal"); + println("Warming up the JVM..."); + final long t1 = System.nanoTime(); + + // warmup at least 2 rounds and at most 1 minute + final long stop = System.currentTimeMillis() + (60 * 1000); + for (int i = 0; i < 10; i++) { + final int LINES = throughput ? 50000 : 200000; + runTest(runner, LINES, null, warmupHist, 1); + if (i > 0 && System.currentTimeMillis() >= stop) { + return; + } + } + + printf("Warmup complete in %.1f seconds%n", (System.nanoTime() - t1) + / (1000.0 * 1000.0 * 1000.0)); + println("Waiting 10 seconds for buffers to drain warmup data..."); + Thread.sleep(10000); + + println("Starting the main test..."); + // test + throughput = false; + runSingleThreadedTest(runner, name, resultFile); + + Thread.sleep(1000); + + throughput = true; + runSingleThreadedTest(runner, name, resultFile); + } + + private int runSingleThreadedTest(final IPerfTestRunner runner, final String name, + final String resultFile) throws IOException { + final Histogram latency = createHistogram(); + final int LINES = throughput ? 50000 : 5000000; + runTest(runner, LINES, "end", latency, 1); + reportResult(resultFile, name, latency); + return LINES; + } + + static void reportResult(final String file, final String name, final Histogram histogram) + throws IOException { + final String result = createSamplingReport(name, histogram); + println(result); + + if (file != null) { + final FileWriter writer = new FileWriter(file, true); + writer.write(result); + writer.write(System.getProperty("line.separator")); + writer.close(); + } + } + + static void printf(final String msg, final Object... objects) { + if (verbose) { + System.out.printf(msg, objects); + } + } + + static void println(final String msg) { + if (verbose) { + System.out.println(msg); + } + } + + static String createSamplingReport(final String name, final Histogram histogram) { + final Histogram data = histogram; + if (throughput) { + return data.getMax() + " operations/second"; + } + final String result = String.format( + "avg=%.0f 99%%=%d 99.99%%=%d sampleCount=%d", data.getMean(), // + data.getTwoNinesUpperBound(), // + data.getFourNinesUpperBound(), // + data.getCount() // + ); + return result; + } + + public void runTest(final IPerfTestRunner runner, final int lines, final String finalMessage, + final Histogram histogram, final int threadCount) { + if (throughput) { + runner.runThroughputTest(lines, histogram); + } else { + final long nanoTimeCost = calcNanoTimeCost(); + runner.runLatencyTest(lines, histogram, nanoTimeCost, threadCount); + } + if (finalMessage != null) { + runner.log(finalMessage); + } + } } Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestResultFormatter.java URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestResultFormatter.java?rev=1514565&r1=1514564&r2=1514565&view=diff ============================================================================== --- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestResultFormatter.java (original) +++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestResultFormatter.java Fri Aug 16 03:33:52 2013 @@ -33,150 +33,150 @@ import java.util.TreeMap; * format it for pasting into Excel. */ class PerfTestResultFormatter { - static final String LF = System.getProperty("line.separator"); - static final NumberFormat NUM = new DecimalFormat("#,##0"); + static final String LF = System.getProperty("line.separator"); + static final NumberFormat NUM = new DecimalFormat("#,##0"); - static class Stats { - long throughput; - double avgLatency; - double latency99Pct; - double latency99_99Pct; - - Stats(final String throughput, final String avg, final String lat99, final String lat99_99) - throws ParseException { - this.throughput = NUM.parse(throughput.trim()).longValue(); - this.avgLatency = Double.parseDouble(avg.trim()); - this.latency99Pct = Double.parseDouble(lat99.trim()); - this.latency99_99Pct = Double.parseDouble(lat99_99.trim()); - } - } - - private final Map> results = new TreeMap>(); - - public PerfTestResultFormatter() { - } - - public String format(final String text) throws ParseException { - results.clear(); - final String[] lines = text.split("[\\r\\n]+"); - for (final String line : lines) { - process(line); - } - return latencyTable() + LF + throughputTable(); - } - - private String latencyTable() { - final StringBuilder sb = new StringBuilder(4 * 1024); - final Set subKeys = results.values().iterator().next().keySet(); - final char[] tabs = new char[subKeys.size()]; - Arrays.fill(tabs, '\t'); - final String sep = new String(tabs); - sb.append("\tAverage latency").append(sep).append("99% less than").append(sep).append("99.99% less than"); - sb.append(LF); - for (int i = 0; i < 3; i++) { - for (final String subKey : subKeys) { - sb.append("\t").append(subKey); - } - } - sb.append(LF); - for (final String key : results.keySet()) { - sb.append(key); - for (int i = 0; i < 3; i++) { - final Map sub = results.get(key); - for (final String subKey : sub.keySet()) { - final Stats stats = sub.get(subKey); - switch (i) { - case 0: - sb.append("\t").append((long) stats.avgLatency); - break; - case 1: - sb.append("\t").append((long) stats.latency99Pct); - break; - case 2: - sb.append("\t").append((long) stats.latency99_99Pct); - break; - } - } - } - sb.append(LF); - } - return sb.toString(); - } - - private String throughputTable() { - final StringBuilder sb = new StringBuilder(4 * 1024); - final Set subKeys = results.values().iterator().next().keySet(); - sb.append("\tThroughput per thread (msg/sec)"); - sb.append(LF); - for (final String subKey : subKeys) { - sb.append("\t").append(subKey); - } - sb.append(LF); - for (final String key : results.keySet()) { - sb.append(key); - final Map sub = results.get(key); - for (final String subKey : sub.keySet()) { - final Stats stats = sub.get(subKey); - sb.append("\t").append(stats.throughput); - } - sb.append(LF); - } - return sb.toString(); - } - - private void process(final String line) throws ParseException { - final String key = line.substring(line.indexOf('.') + 1, line.indexOf('(')); - final String sub = line.substring(line.indexOf('(') + 1, line.indexOf(')')); - final String throughput = line.substring(line.indexOf("throughput: ") - + "throughput: ".length(), line.indexOf(" ops")); - final String avg = line.substring(line.indexOf("avg=") + "avg=".length(), - line.indexOf(" 99%")); - final String pct99 = line.substring( - line.indexOf("99% < ") + "99% < ".length(), - line.indexOf(" 99.99%")); - final String pct99_99 = line.substring(line.indexOf("99.99% < ") - + "99.99% < ".length(), line.lastIndexOf('(') - 1); - final Stats stats = new Stats(throughput, avg, pct99, pct99_99); - Map map = results.get(key.trim()); - if (map == null) { - map = new TreeMap(sort()); - results.put(key.trim(), map); - } - String subKey = sub.trim(); - if ("single thread".equals(subKey)) { - subKey = "1 thread"; - } - map.put(subKey, stats); - } - - private Comparator sort() { - return new Comparator() { - List expected = Arrays.asList("1 thread", "2 threads", - "4 threads", "8 threads", "16 threads", "32 threads", - "64 threads"); - - @Override - public int compare(final String o1, final String o2) { - final int i1 = expected.indexOf(o1); - final int i2 = expected.indexOf(o2); - if (i1 < 0 || i2 < 0) { - return o1.compareTo(o2); - } - return i1 - i2; - } - }; - } - - public static void main(final String[] args) throws Exception { - final PerfTestResultFormatter fmt = new PerfTestResultFormatter(); - final BufferedReader reader = new BufferedReader(new InputStreamReader( - System.in)); - String line; - while ((line = reader.readLine()) != null) { - fmt.process(line); - } - System.out.println(fmt.latencyTable()); - System.out.println(); - System.out.println(fmt.throughputTable()); - } + static class Stats { + long throughput; + double avgLatency; + double latency99Pct; + double latency99_99Pct; + + Stats(final String throughput, final String avg, final String lat99, final String lat99_99) + throws ParseException { + this.throughput = NUM.parse(throughput.trim()).longValue(); + this.avgLatency = Double.parseDouble(avg.trim()); + this.latency99Pct = Double.parseDouble(lat99.trim()); + this.latency99_99Pct = Double.parseDouble(lat99_99.trim()); + } + } + + private final Map> results = new TreeMap>(); + + public PerfTestResultFormatter() { + } + + public String format(final String text) throws ParseException { + results.clear(); + final String[] lines = text.split("[\\r\\n]+"); + for (final String line : lines) { + process(line); + } + return latencyTable() + LF + throughputTable(); + } + + private String latencyTable() { + final StringBuilder sb = new StringBuilder(4 * 1024); + final Set subKeys = results.values().iterator().next().keySet(); + final char[] tabs = new char[subKeys.size()]; + Arrays.fill(tabs, '\t'); + final String sep = new String(tabs); + sb.append("\tAverage latency").append(sep).append("99% less than").append(sep).append("99.99% less than"); + sb.append(LF); + for (int i = 0; i < 3; i++) { + for (final String subKey : subKeys) { + sb.append("\t").append(subKey); + } + } + sb.append(LF); + for (final String key : results.keySet()) { + sb.append(key); + for (int i = 0; i < 3; i++) { + final Map sub = results.get(key); + for (final String subKey : sub.keySet()) { + final Stats stats = sub.get(subKey); + switch (i) { + case 0: + sb.append("\t").append((long) stats.avgLatency); + break; + case 1: + sb.append("\t").append((long) stats.latency99Pct); + break; + case 2: + sb.append("\t").append((long) stats.latency99_99Pct); + break; + } + } + } + sb.append(LF); + } + return sb.toString(); + } + + private String throughputTable() { + final StringBuilder sb = new StringBuilder(4 * 1024); + final Set subKeys = results.values().iterator().next().keySet(); + sb.append("\tThroughput per thread (msg/sec)"); + sb.append(LF); + for (final String subKey : subKeys) { + sb.append("\t").append(subKey); + } + sb.append(LF); + for (final String key : results.keySet()) { + sb.append(key); + final Map sub = results.get(key); + for (final String subKey : sub.keySet()) { + final Stats stats = sub.get(subKey); + sb.append("\t").append(stats.throughput); + } + sb.append(LF); + } + return sb.toString(); + } + + private void process(final String line) throws ParseException { + final String key = line.substring(line.indexOf('.') + 1, line.indexOf('(')); + final String sub = line.substring(line.indexOf('(') + 1, line.indexOf(')')); + final String throughput = line.substring(line.indexOf("throughput: ") + + "throughput: ".length(), line.indexOf(" ops")); + final String avg = line.substring(line.indexOf("avg=") + "avg=".length(), + line.indexOf(" 99%")); + final String pct99 = line.substring( + line.indexOf("99% < ") + "99% < ".length(), + line.indexOf(" 99.99%")); + final String pct99_99 = line.substring(line.indexOf("99.99% < ") + + "99.99% < ".length(), line.lastIndexOf('(') - 1); + final Stats stats = new Stats(throughput, avg, pct99, pct99_99); + Map map = results.get(key.trim()); + if (map == null) { + map = new TreeMap(sort()); + results.put(key.trim(), map); + } + String subKey = sub.trim(); + if ("single thread".equals(subKey)) { + subKey = "1 thread"; + } + map.put(subKey, stats); + } + + private Comparator sort() { + return new Comparator() { + List expected = Arrays.asList("1 thread", "2 threads", + "4 threads", "8 threads", "16 threads", "32 threads", + "64 threads"); + + @Override + public int compare(final String o1, final String o2) { + final int i1 = expected.indexOf(o1); + final int i2 = expected.indexOf(o2); + if (i1 < 0 || i2 < 0) { + return o1.compareTo(o2); + } + return i1 - i2; + } + }; + } + + public static void main(final String[] args) throws Exception { + final PerfTestResultFormatter fmt = new PerfTestResultFormatter(); + final BufferedReader reader = new BufferedReader(new InputStreamReader( + System.in)); + String line; + while ((line = reader.readLine()) != null) { + fmt.process(line); + } + System.out.println(fmt.latencyTable()); + System.out.println(); + System.out.println(fmt.throughputTable()); + } } \ No newline at end of file Modified: logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/RunLogback.java URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/RunLogback.java?rev=1514565&r1=1514564&r2=1514565&view=diff ============================================================================== --- logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/RunLogback.java (original) +++ logging/log4j/log4j2/trunk/core/src/test/java/org/apache/logging/log4j/core/async/perftest/RunLogback.java Fri Aug 16 03:33:52 2013 @@ -25,47 +25,47 @@ import com.lmax.disruptor.collections.Hi public class RunLogback implements IPerfTestRunner { - @Override - public void runThroughputTest(final int lines, final Histogram histogram) { - final long s1 = System.nanoTime(); - final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); - for (int j = 0; j < lines; j++) { - logger.info(THROUGHPUT_MSG); - } - final long s2 = System.nanoTime(); - final long opsPerSec = (1000L * 1000L * 1000L * lines) / (s2 - s1); - histogram.addObservation(opsPerSec); - } + @Override + public void runThroughputTest(final int lines, final Histogram histogram) { + final long s1 = System.nanoTime(); + final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); + for (int j = 0; j < lines; j++) { + logger.info(THROUGHPUT_MSG); + } + final long s2 = System.nanoTime(); + final long opsPerSec = (1000L * 1000L * 1000L * lines) / (s2 - s1); + histogram.addObservation(opsPerSec); + } - @Override - public void runLatencyTest(final int samples, final Histogram histogram, - final long nanoTimeCost, final int threadCount) { - final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); - 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); - } - // wait 1 microsec - final long PAUSE_NANOS = 10000 * threadCount; - final long pauseStart = System.nanoTime(); - while (PAUSE_NANOS > (System.nanoTime() - pauseStart)) { - // busy spin - } - } - } + @Override + public void runLatencyTest(final int samples, final Histogram histogram, + final long nanoTimeCost, final int threadCount) { + final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); + 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); + } + // wait 1 microsec + final long PAUSE_NANOS = 10000 * threadCount; + final long pauseStart = System.nanoTime(); + while (PAUSE_NANOS > (System.nanoTime() - pauseStart)) { + // busy spin + } + } + } - @Override - public void shutdown() { - ((LifeCycle) LoggerFactory.getILoggerFactory()).stop(); - } + @Override + public void shutdown() { + ((LifeCycle) LoggerFactory.getILoggerFactory()).stop(); + } - @Override - public void log(final String msg) { - final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); - logger.info(msg); - } + @Override + public void log(final String msg) { + final Logger logger = (Logger) LoggerFactory.getLogger(getClass()); + logger.info(msg); + } }