All Downloads are FREE. Search and download functionalities are using the official Maven repository.

org.mentalog.test.PerformanceComparator Maven / Gradle / Ivy

Go to download

A log library that embraces the kiss principle.

There is a newer version: 2.1.2
Show newest version
package org.mentalog.test;

import static org.mentalog.Log.*;

import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;
import org.mentalog.Log;
import org.mentalog.util.Benchmarker;
import org.mentalog.util.DetailedBenchmarker;
import org.mentalog.util.SystemUtils;
import org.slf4j.LoggerFactory;

/**
 * Results:
 * 
 * - MentaLog: (no memory-mapped and no async logging)
 * 
 * java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=false -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 mentalog
 * 
 * Iterations: 900000 | Avg Time: 4317.79 nanos | Min Time: 4025 nanos | Max Time: 935349 nanos
 * Iterations: 1800000 | Avg Time: 4148.65 nanos | Min Time: 3806 nanos | Max Time: 2836875 nanos
 * Iterations: 4500000 | Avg Time: 4278.94 nanos | Min Time: 3871 nanos | Max Time: 38635829 nanos
 * 
 * ==== Memory allocated: ZERO (not a single byte) ====
 * 
 * - Log4J:
 * 
 * java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=false -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 log4j
 *
 * Iterations: 90000 | Avg Time: 3756.18 nanos | Min Time: 2787 nanos | Max Time: 150017 nanos
 * Iterations: 900000 | Avg Time: 3329.19 nanos | Min Time: 2756 nanos | Max Time: 654025 nanos
 * Iterations: 4500000 | Avg Time: 3280.86 nanos | Min Time: 2859 nanos | Max Time: 6879898 nanos
 * 
 * Memory is allocated and GC is triggered
 *
 * - Logback:
 * 
 * java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=false -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 logback
 *
 * Iterations: 900000 | Avg Time: 3750.77 nanos | Min Time: 3158 nanos | Max Time: 648638 nanos
 * Iterations: 1800000 | Avg Time: 3618.32 nanos | Min Time: 3130 nanos | Max Time: 4684685 nanos
 * Iterations: 4500000 | Avg Time: 3701.08 nanos | Min Time: 3200 nanos | Max Time: 55608669 nanos
 * 
 * Memory is allocated and GC is triggered
 * 
 * - MentaLog: (with memory-mapped file)
 * 
 * java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=true -DlogMemoryMappedBufferSize=150m -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog
 *
 * Iterations: 900000 | Avg Time: 1294.71 nanos | Min Time: 1204 nanos | Max Time: 101816 nanos
 * Iterations: 1800000 | Avg Time: 1310.23 nanos | Min Time: 1209 nanos | Max Time: 169474 nanos
 * Iterations: 1800000 | Avg Time: 1281.92 nanos | Min Time: 1201 nanos | Max Time: 687653 nanos
 * 
 * ==== Memory allocated: ZERO (not a single byte) ====
 * 
 * - MentaLog: (with asynchronous logging) NOTE: Thread pinning might be a good idea here!
 * 
 * java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=false -DlogMemoryMappedBufferSize=150m -DlogAsynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 5000000 mentalog
 * 
 * Iterations: 900000 | Avg Time: 3808.65 nanos | Min Time: 97 nanos | Max Time: 20100420 nanos | 75%: 150 nanos | 90%: 156 nanos | 99%: 164 nanos | 99.9%: 167 nanos | 99.99%: 1890 nanos | 99.999%: 3609 nanos
 * Iterations: 1800000 | Avg Time: 3832.35 nanos | Min Time: 100 nanos | Max Time: 20269036 nanos | 75%: 146 nanos | 90%: 153 nanos | 99%: 160 nanos | 99.9%: 162 nanos | 99.99%: 2128 nanos | 99.999%: 3651 nanos
 * Iterations: 4500000 | Avg Time: 3624.02 nanos | Min Time: 99 nanos | Max Time: 25602060 nanos | 75%: 149 nanos | 90%: 156 nanos | 99%: 163 nanos | 99.9%: 165 nanos | 99.99%: 1734 nanos | 99.999%: 3424 nanos
 * 
 * ==== Memory allocated: ZERO (not a single byte) ====
 * 
 * - MentaLog: (with asynchronous logging AND memory-mapped files) NOTE: Thread pinning might make this even better!
 * 
 * java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=true -DlogMemoryMappedBufferSize=300m -DlogAsynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 2000000 mentalog
 * 
 * Iterations: 4500000 | Avg Time: 969.62 nanos | Min Time: 97 nanos | Max Time: 5229828 nanos | 75%: 178 nanos | 90%: 188 nanos | 99%: 198 nanos | 99.9%: 200 nanos | 99.99%: 500 nanos | 99.999%: 920 nanos
 * Iterations: 1800000 | Avg Time: 973.22 nanos | Min Time: 92 nanos | Max Time: 5024597 nanos | 75%: 164 nanos | 90%: 174 nanos | 99%: 184 nanos | 99.9%: 186 nanos | 99.99%: 519 nanos | 99.999%: 925 nanos
 * Iterations: 900000 | Avg Time: 973.94 nanos | Min Time: 98 nanos | Max Time: 6461357 nanos | 75%: 166 nanos | 90%: 176 nanos | 99%: 187 nanos | 99.9%: 189 nanos | 99.99%: 380 nanos | 99.999%: 911 nanos
 * 
 * ==== Memory allocated: ZERO (not a single byte) ====
 * 
 * - Log4J: (with asynchronous logging) NOTE: Changet the log4j xml file to use asynchronous logging
 * 
 * Iterations: 4500000 | Avg Time: 2566.31 nanos | Min Time: 260 nanos | Max Time: 31647565 nanos | 75%: 273 nanos | 90%: 281 nanos | 99%: 288 nanos | 99.9%: 290 nanos | 99.99%: 292 nanos | 99.999%: 2317 nanos
 * Iterations: 1800000 | Avg Time: 2510.84 nanos | Min Time: 263 nanos | Max Time: 25864561 nanos | 75%: 281 nanos | 90%: 295 nanos | 99%: 307 nanos | 99.9%: 314 nanos | 99.99%: 317 nanos | 99.999%: 2264 nanos
 * Iterations: 900000 | Avg Time: 2747.56 nanos | Min Time: 260 nanos | Max Time: 28432739 nanos | 75%: 276 nanos | 90%: 285 nanos | 99%: 301 nanos | 99.9%: 313 nanos | 99.99%: 316 nanos | 99.999%: 2478 nanos
 * 
 * A lot of memory is allocated and GC is triggered
 * 
 * @author soliveira
 *
 */
public class PerformanceComparator {

	private enum LogLibrary {
		LOG4J, MENTALOG, LOGBACK
	};

	private static final String MSG = "This is a log message not so small that you can use to test. I hope you have fun and it works well!";

	private static final String FORMAT = "format HeapTest  ";

	public static void main(final String[] args) {

		// no memory-mapped files and no asynchronous logging:

		// java -verbose:gc -cp target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=false -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog

		// with memory-mapped files: (requires extension in front of the classpath)

		// java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=true -DlogMemoryMappedBufferSize=150m -DlogAsynchronous=false -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog

		// with memory-mapped files and asynchronous logging using MentaQueue: (requires extension in front of the classpath)

		// java -verbose:gc -cp ../MentaLogExt/target/mentalogext.jar:target/classes:lib/slf4j-api-1.6.2.jar:lib/logback-core-0.9.30.jar:lib/logback-classic-0.9.30.jar:lib/log4j-1.2.16.jar:lib/menta-queue-0.9.3.jar:src/main/java/org/mentalog/test -DlogMemoryMappedFile=true -DlogMemoryMappedBufferSize=150m -DlogAsynchronous=true -Dlogback.configurationFile=./src/main/java/org/mentalog/test/logback.xml -Xms1g -Xmx4g -XX:NewSize=512m -XX:MaxNewSize=1024m org.mentalog.test.PerformanceComparator 1000000 mentalog

		if (args.length != 2) {
			System.out.println(FORMAT);
			return;
		}

		LogLibrary logLibrary = null;

		try {
			logLibrary = Enum.valueOf(LogLibrary.class, args[1].toUpperCase());
		}
		catch (final Exception e) {
			System.err.println("Cannot parse log library: " + args[1]);
			System.out.println(FORMAT);
			return;
		}

		final int max = Integer.parseInt(args[0]);
		int warmup = (int) Math.round(0.1 * max);

		long totalMemory = 0;
		long logsWithNoMemory = 0;
		long logsWithMemory = 0;
		long logsTotal = 0;
		long logsGC = 0;
		
		// please note that detailed benchmark produces garbage when measuring so it cannot be used when you want to profile the gc...
		boolean isDetailed = SystemUtils.getBoolean("detailedBenchmark", false);

		final Benchmarker bench = isDetailed ? new DetailedBenchmarker(warmup) : new DetailedBenchmarker(warmup);

		setup(logLibrary);

		System.out.println("Performing GC before starting...");
		System.gc();
		try {
			Thread.sleep(1000);
		}
		catch (final Exception e) {}
		System.out.println("Starting...");
		
		long freeMemory = 0;
		long mem = 0;

		for (int i = 1; i <= max; i++) {
			freeMemory = Runtime.getRuntime().freeMemory();
			bench.mark();
			log(logLibrary);
			bench.measure();
			mem = freeMemory - Runtime.getRuntime().freeMemory();
			logsTotal++;
			if (mem > 0) {
				// System.out.println("Created " + mem + " bytes after " + i + " log calls");
				totalMemory += mem;
				logsWithMemory++;
			}
			else if (mem == 0) {
				logsWithNoMemory++;
			}
			else {
				// System.out.println("GC called!");
				logsGC++;
			}
		}

		Log.stop();

		System.out.println("Wrote " + logsTotal + " log lines to a file!");
		if (!isDetailed) {
			System.out.println("Logs that allocated memory: " + logsWithMemory + " (" + p(logsWithMemory, logsTotal) + ")");
			System.out.println("Logs that did not allocate any memory: " + logsWithNoMemory + " (" + p(logsWithNoMemory, logsTotal) + ")");
			System.out.println("Logs that triggered GC: " + logsGC + " (" + p(logsGC, logsTotal) + ")");
			System.out.println("Memory allocated: " + totalMemory + " bytes");
		}
		System.out.println("Benchmark: " + bench.results());
		System.out.println();
	}

	private static org.slf4j.Logger logger_logback = null;
	private static org.apache.log4j.Logger logger_log4j = null;

	private final static void setup(final LogLibrary logLibrary) {
		if (logLibrary == LogLibrary.MENTALOG) {
			Log.setFile(true);
			Warn.log(MSG); // force the log to open to create the file and get ready to log (that of course creates memory!)
		}
		else if (logLibrary == LogLibrary.LOGBACK) {
			logger_logback = LoggerFactory.getLogger("chapters.introduction.HelloWorld1");
			logger_logback.warn(MSG);
		}
		else if (logLibrary == LogLibrary.LOG4J) {
			PropertyConfigurator.configure("./src/main/java/org/mentalog/test/log4j.xml");
			logger_log4j = Logger.getLogger(GCTest.class);
			logger_log4j.warn(MSG);
		}
	}

	private final static void log(final LogLibrary logLibrary) {
		if (logLibrary == LogLibrary.MENTALOG) {
			Warn.log(MSG);
		}
		else if (logLibrary == LogLibrary.LOGBACK) {
			logger_logback.warn(MSG);
		}
		else if (logLibrary == LogLibrary.LOG4J) {
			logger_log4j.warn(MSG);
		}
	}

	private static String p(final long l, final long total) {
		final double d = ((double) l) / ((double) total) * 100D;
		final double rounded = Math.round(d * 100) / 100D;
		return String.valueOf(rounded) + "%";
	}
}




© 2015 - 2024 Weber Informatics LLC | Privacy Policy