Repository: logging-log4j2 Updated Branches: refs/heads/master 9660677ff -> 873beebf4
LOG4J2-1278 removed old Unbox class from perf.nogc package Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/873beebf Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/873beebf Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/873beebf Branch: refs/heads/master Commit: 873beebf413b5ad33839bd0ae17b5de1cc6a5e37 Parents: 9660677 Author: rpopma <[email protected]> Authored: Sun Apr 3 01:01:56 2016 +0900 Committer: rpopma <[email protected]> Committed: Sun Apr 3 01:01:56 2016 +0900 ---------------------------------------------------------------------- .../core/async/perftest/SimplePerfTest.bat | 22 +++- .../core/async/perftest/SimplePerfTest.java | 112 ++++++++++++++----- 2 files changed, 99 insertions(+), 35 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/873beebf/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.bat ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.bat b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.bat index c1965ff..31ef72b 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.bat +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.bat @@ -1,20 +1,32 @@ @echo off REM reject if no arg supplied -IF %1.==. echo Usage: %0 version & exit /b +IF %1.==. echo Usage: %0 version [core-version] & exit /b +IF %2.==. set %2=%1 -set GC_OPTIONS=-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime set GC_OPTIONS= +:set GC_OPTIONS=-XX:+UnlockDiagnosticVMOptions -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime +:set GC_OPTIONS=-XX:+PrintCompilation +set LOG4J_OPTIONS= set LOG4J_OPTIONS=-Dlog4j.configurationFile=perf-CountingNoOpAppender.xml :set LOG4J_OPTIONS=-Dlog4j.configurationFile=perf3PlainNoLoc.xml set LOG4J_OPTIONS=%LOG4J_OPTIONS% -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -set LOG4J_OPTIONS=%LOG4J_OPTIONS% -Dlog4j2.enable.threadlocals=true +:set LOG4J_OPTIONS=%LOG4J_OPTIONS% -Dlog4j2.enable.threadlocals=true +:set LOG4J_OPTIONS=%LOG4J_OPTIONS% -DAsyncLogger.WaitStrategy=Yield +:set LOG4J_OPTIONS=%LOG4J_OPTIONS% -DAsyncLogger.RingBufferSize=262144 +REM Java Flight Recorder settings: %JAVA_HOME%jre\lib\jfr\default.jfc +REM Tip: set all 3 settings for "allocation-profiling-enabled" to true +set JFR_OPTIONS= +set JFR_OPTIONS=-XX:+UnlockCommercialFeatures -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:+FlightRecorder +set JFR_OPTIONS=%JFR_OPTIONS% -XX:StartFlightRecording=duration=60s,filename=log4j-%1.jfr + +set CP= set CP=log4j-api-%1.jar;log4j-core-%1.jar;disruptor-3.3.4.jar;log4j-1.2.17.jar;slf4j-api-1.7.13.jar;logback-classic-1.1.3.jar;logback-core-1.1.3.jar set CP=%CP%;C:\Users\remko\IdeaProjects\logging-log4j2\log4j-core\target\test-classes -:set CP=%CP%;log4j-core-2.0-tests.jar +:set CP=%CP%;log4j-core-2.6-SNAPSHOT-tests.jar set MAIN=org.apache.logging.log4j.core.async.perftest.SimplePerfTest @echo on -java -Xms128m -Xmx128m %GC_OPTIONS% %LOG4J_OPTIONS% -cp %CP% %MAIN% +java -Xms256M -Xmx256M %JFR_OPTIONS% %GC_OPTIONS% %LOG4J_OPTIONS% -cp %CP% %MAIN% http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/873beebf/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.java index 5eeeed1..d886d00 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/SimplePerfTest.java @@ -16,19 +16,28 @@ */ package org.apache.logging.log4j.core.async.perftest; +import java.lang.management.GarbageCollectorMXBean; import java.lang.management.ManagementFactory; import java.lang.management.RuntimeMXBean; +import java.lang.reflect.Method; +import java.util.List; import java.util.concurrent.TimeUnit; 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.AsyncLoggerContext; import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector; +import org.apache.logging.log4j.spi.LoggerContext; /** * Created by remko on 2/26/2016. + * + * -XX:+UnlockDiagnosticVMOptions -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime */ public class SimplePerfTest { + static final int ITERATIONS = 100000; + public static void main(String[] args) throws Exception { System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName()); @@ -36,50 +45,82 @@ public class SimplePerfTest { if (!(logger instanceof AsyncLogger)) { throw new IllegalStateException(); } - logger.info("Starting..."); + // work around a bug in Log4j-2.5 + workAroundLog4j2_5Bug(); + + logger.error("Starting..."); + System.out.println("Starting..."); Thread.sleep(100); final RuntimeMXBean runtimeMXBean = ManagementFactory.getRuntimeMXBean(); + final long testStartNanos = System.nanoTime(); + final long[] UPTIMES = new long[1024]; + final long[] DURATIONS = new long[1024]; // warmup - final int ITERATIONS = 100000; long startMs = System.currentTimeMillis(); long end = startMs + TimeUnit.SECONDS.toMillis(10); - long total = 0; - int count = 0; - StringBuilder sb = new StringBuilder(512); + int warmupCount = 0; do { - sb.setLength(0); - long startNanos = System.nanoTime(); - long uptime = runtimeMXBean.getUptime(); - loop(logger, ITERATIONS); - long endNanos = System.nanoTime(); - long durationNanos = endNanos - startNanos; - final long opsPerSec = (1000L * 1000L * 1000L * ITERATIONS) / durationNanos; - sb.append(uptime).append(" Warmup: Throughput: ").append(opsPerSec).append(" ops/s"); - System.out.println(sb); - total += opsPerSec; - count++; + runTest(logger, runtimeMXBean, UPTIMES, DURATIONS, warmupCount); + warmupCount++; // Thread.sleep(1000);// drain buffer } while (System.currentTimeMillis() < end); - System.out.printf("Average warmup throughput: %,d ops/s%n", total/count); final int COUNT = 10; - final long[] durationNanos = new long[10]; for (int i = 0; i < COUNT; i++) { - final long startNanos = System.nanoTime(); - loop(logger, ITERATIONS); - long endNanos = System.nanoTime(); - durationNanos[i] = endNanos - startNanos; + int count = warmupCount + i; + runTest(logger, runtimeMXBean, UPTIMES, DURATIONS, count); // Thread.sleep(1000);// drain buffer } - total = 0; - for (int i = 0; i < COUNT; i++) { - final long opsPerSec = (1000L * 1000L * 1000L * ITERATIONS) / durationNanos[i]; - System.out.printf("Throughput: %,d ops/s%n", opsPerSec); + double testDurationNanos = System.nanoTime() - testStartNanos; + System.out.println("Done. Calculating stats..."); + + printReport("Warmup", UPTIMES, DURATIONS, 0, warmupCount); + printReport("Test", UPTIMES, DURATIONS, warmupCount, COUNT); + + StringBuilder sb = new StringBuilder(512); + sb.append("Test took: ").append(testDurationNanos/(1000.0*1000.0*1000.0)).append(" sec"); + System.out.println(sb); + + final List<GarbageCollectorMXBean> gcBeans = ManagementFactory.getGarbageCollectorMXBeans(); + for (int i = 0; i < gcBeans.size(); i++) { + GarbageCollectorMXBean gcBean = gcBeans.get(i); + sb.setLength(0); + sb.append("GC[").append(gcBean.getName()).append("] "); + sb.append(gcBean.getCollectionCount()).append(" collections, collection time="); + sb.append(gcBean.getCollectionTime()).append(" millis."); + System.out.println(sb); + } + } + + private static void printReport(final String label, final long[] UPTIMES, final long[] DURATIONS, + final int offset, final int length) { + StringBuilder sb = new StringBuilder(512); + long total = 0; + for (int i = offset; i < offset + length; i++) { + sb.setLength(0); + final long opsPerSec = (1000L * 1000L * 1000L * ITERATIONS) / DURATIONS[i]; total += opsPerSec; + sb.append(UPTIMES[i]).append(" "); + sb.append(label).append(": Throughput: ").append(opsPerSec).append(" ops/s"); + System.out.println(sb); } - System.out.printf("Average throughput: %,d ops/s%n", total/COUNT); + sb.setLength(0); + sb.append("Average ").append(label).append(" throughput: ").append(total/length).append(" ops/s"); + System.out.println(sb); + + sb.setLength(0); + System.out.println(sb.append(label).append(" ran: ").append(length).append(" iterations")); + } + + private static void runTest(final Logger logger, final RuntimeMXBean runtimeMXBean, final long[] UPTIMES, + final long[] DURATIONS, final int index) { + UPTIMES[index] = runtimeMXBean.getUptime(); + long startNanos = System.nanoTime(); + loop(logger, ITERATIONS); + long endNanos = System.nanoTime(); + DURATIONS[index] = endNanos - startNanos; } private static void loop(final Logger logger, final int iterations) { @@ -87,10 +128,21 @@ public class SimplePerfTest { // String[] arg2 = new String[] {"arg1", "arg2", }; // for (int i = 0; i < iterations; i ++) { -// logger.info("7 arg message {} {} {} {} {} {} {}"); -// logger.info("7 arg message {} {} "); +// logger.error("7 arg message {} {} {} {} {} {} {}"); +// logger.error("7 arg message {} {} "); + + logger.error("simple text message"); + } + } - logger.info("simple text message"); + private static void workAroundLog4j2_5Bug() { + // use reflection so we can use the same test with older versions of log4j2 + try { + Method setUseThreadLocals = + AsyncLoggerContext.class.getDeclaredMethod("setUseThreadLocals", new Class[]{boolean.class}); + LoggerContext context = LogManager.getContext(false); + setUseThreadLocals.invoke(context, new Object[] {Boolean.TRUE}); + } catch (Throwable ignored) { } } }
