Created
August 7, 2013 18:55
-
-
Save cdman/6177268 to your computer and use it in GitHub Desktop.
Additional Log4jv2 tests
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
/* | |
* 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); | |
} | |
} |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
/* | |
* 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); | |
} | |
} |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment