Additional Log4jv2 tests

Additional info

Command line + environment:

Ubuntu 13.04 64 bit, OpenJDK 7u25-2.3.10-1ubuntu0.13.04.2
CPU: Intel(R) Core(TM) i7-2760QM CPU @ 2.40GHz

JVM Params: -server -XX:+UnlockDiagnosticVMOptions -XX:+AggressiveOpts -Dlog4j.configurationFile=perf5AsyncApndNoLoc.xml
(I modified perf5AsyncApndNoLoc such that it writes to /dev/null rather than a physical file)

Unmodified run:
avg=6 99%=32 99.99%=512 sampleCount=3986503

Modified as per Gil's suggestion (adding "missing" values):
avg=6 99%=16 99.99%=512 sampleCount=3890210

Alternative solution - execute multiple logger.info calls between System.nanoTime to eliminate its overhead and average over it:
avg=2 99%=16 99.99%=256 sampleCount=4999970

RunLog4j2 - Attilas Version.java

/*
 * Licensed to the Apache Software Foundation (ASF) under one or more
 * contributor license agreements. See the NOTICE file distributed with
 * this work for additional information regarding copyright ownership.
 * The ASF licenses this file to You under the Apache license, Version 2.0
 * (the "License"); you may not use this file except in compliance with
 * the License. You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the license for the specific language governing permissions and
 * limitations under the license.
 */
package org.apache.logging.log4j.core.async.perftest;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LifeCycle;

import com.lmax.disruptor.collections.Histogram;

public class RunLog4j2 implements IPerfTestRunner {

	@Override
	public void runThroughputTest(final int lines, final Histogram histogram) {
		final long s1 = System.nanoTime();
		final Logger logger = LogManager.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 = LogManager.getLogger(getClass());
		final long doubleNanoTimeCost = 2*nanoTimeCost;
		final long iterationSamples = samples / doubleNanoTimeCost;
		for (int i = 0; i < iterationSamples; i++) {
			final long s1 = System.nanoTime();
			for (int j = 0; j < doubleNanoTimeCost; j++) {
				logger.info(LATENCY_MSG);
			}
			final long s2 = System.nanoTime();
			final long value = (s2 - s1) / doubleNanoTimeCost;
			for (int j = 0; j < doubleNanoTimeCost; j++) {
				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) LogManager.getContext()).stop(); // stop async thread
	}

	@Override
	public void log(final String finalMessage) {
		final Logger logger = LogManager.getLogger(getClass());
		logger.info(finalMessage);
	}
}

RunLog4j2 - Gils Version.java

/*
 * Licensed to the Apache Software Foundation (ASF) under one or more
 * contributor license agreements. See the NOTICE file distributed with
 * this work for additional information regarding copyright ownership.
 * The ASF licenses this file to You under the Apache license, Version 2.0
 * (the "License"); you may not use this file except in compliance with
 * the License. You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the license for the specific language governing permissions and
 * limitations under the license.
 */
package org.apache.logging.log4j.core.async.perftest;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LifeCycle;

import com.lmax.disruptor.collections.Histogram;

public class RunLog4j2 implements IPerfTestRunner {

	@Override
	public void runThroughputTest(final int lines, final Histogram histogram) {
		final long s1 = System.nanoTime();
		final Logger logger = LogManager.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 = LogManager.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;

			// Compensate for missing samples:
			long remainingValue = value - PAUSE_NANOS;
			while (remainingValue >= PAUSE_NANOS) {
				histogram.addObservation(remainingValue);
				remainingValue -= PAUSE_NANOS;
			}

			final long pauseStart = System.nanoTime();
			while (PAUSE_NANOS > (System.nanoTime() - pauseStart)) {
				// busy spin
			}
		}
	}

	@Override
	public void shutdown() {
		((LifeCycle) LogManager.getContext()).stop(); // stop async thread
	}

	@Override
	public void log(final String finalMessage) {
		final Logger logger = LogManager.getLogger(getClass());
		logger.info(finalMessage);
	}
}