LOG4J2-1295 Added automated GC-free test. Still @Ignored as of now because the API creates vararg arrays so the test fails.
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/52d04e07 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/52d04e07 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/52d04e07 Branch: refs/heads/LOG4J2-1278-gc-free-logger Commit: 52d04e0779eef09d0826c800cdc0874eea4960e5 Parents: 575cd5b Author: rpopma <[email protected]> Authored: Tue Mar 15 17:25:40 2016 +1100 Committer: rpopma <[email protected]> Committed: Tue Mar 15 17:25:40 2016 +1100 ---------------------------------------------------------------------- .../logging/log4j/core/GcFreeLoggingTest.java | 131 +++++++++++++++++++ 1 file changed, 131 insertions(+) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/52d04e07/log4j-core/src/test/java/org/apache/logging/log4j/core/GcFreeLoggingTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/GcFreeLoggingTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/GcFreeLoggingTest.java new file mode 100644 index 0000000..2cca348 --- /dev/null +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/GcFreeLoggingTest.java @@ -0,0 +1,131 @@ +/* + * 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; + +import java.io.File; +import java.net.URL; +import java.nio.file.Files; + +import com.google.monitoring.runtime.instrumentation.AllocationRecorder; +import com.google.monitoring.runtime.instrumentation.Sampler; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector; +import org.apache.logging.log4j.core.util.Constants; +import org.junit.Ignore; +import org.junit.Test; + +import static org.junit.Assert.*; + +/** + * Verifies steady state logging is GC-free. + * + * @see <a href="https://github.com/google/allocation-instrumenter";>https://github.com/google/allocation-instrumenter</a> + */ +public class GcFreeLoggingTest { + + // ignored: test still fails because of vararg arrays + @Ignore + @Test + public void testNoAllocationDuringSteadyStateLogging() throws Throwable { + final String javaHome = System.getProperty("java.home"); + final String javaBin = javaHome + File.separator + "bin" + File.separator + "java"; + final String classpath = System.getProperty("java.class.path"); + final String javaagent = "-javaagent:" + agentJar(); + + final File tempFile = File.createTempFile("allocations", ".txt"); + tempFile.deleteOnExit(); + + final ProcessBuilder builder = new ProcessBuilder( // + javaBin, javaagent, "-cp", classpath, GcFreeLoggingTest.class.getName()); + builder.redirectError(ProcessBuilder.Redirect.to(tempFile)); + builder.redirectOutput(ProcessBuilder.Redirect.to(tempFile)); + final Process process = builder.start(); + process.waitFor(); + process.exitValue(); + + final String output = new String(Files.readAllBytes(tempFile.toPath())); + assertEquals("", output); + } + + /** + * This code runs in a separate process, instrumented with the Google Allocation Instrumenter. + */ + public static void main(String[] args) throws Exception { + System.setProperty("log4j2.enable.threadlocals", "true"); + System.setProperty("log4j2.is.webapp", "false"); + System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml"); + System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName()); + + assertTrue("Constants.ENABLE_THREADLOCALS", Constants.ENABLE_THREADLOCALS); + assertFalse("Constants.IS_WEB_APP", Constants.IS_WEB_APP); + + // initialize LoggerContext etc. + // This is not steady-state logging and will allocate objects. + final Logger logger = LogManager.getLogger(GcFreeLoggingTest.class.getName()); + logger.debug("debug not set"); + logger.error("Sample error message"); + logger.error("Test parameterized message {}", "param"); + + // BlockingWaitStrategy uses ReentrantLock which allocates Node objects. Ignore this. + final String[] exclude = new String[] { + "java/util/concurrent/locks/AbstractQueuedSynchronizer$Node", // + "com/google/monitoring/runtime/instrumentation/Sampler", // + }; + final Sampler sampler = new Sampler() { + public void sampleAllocation(int count, String desc, Object newObj, long size) { + for (int i = 0; i < exclude.length; i++) { + if (exclude[i].equals(desc)) { + return; // exclude + } + } + System.out.println("I just allocated the object " + newObj + + " of type " + desc + " whose size is " + size); + if (count != -1) { + System.out.println("It's an array of size " + count); + } + + // uncomment to get a stack trace and see which line caused allocation + //new RuntimeException().printStackTrace(); + } + }; + Thread.sleep(500); + AllocationRecorder.addSampler(sampler); + + // now do some steady-state logging + final int ITERATIONS = 5; + for (int i = 0; i < ITERATIONS; i++) { + logger.error("Test message"); + logger.error("Test parameterized message {}", "param"); + logger.error("Test parameterized message {}{}", "param", "param2"); + logger.error("Test parameterized message {}{}{}", "param", "param2", "abc"); + } + AllocationRecorder.removeSampler(sampler); + Thread.sleep(50); + } + + private static File agentJar() { + final String name = AllocationRecorder.class.getName(); + final URL url = AllocationRecorder.class.getResource("/" + name.replace('.', '/').concat(".class")); + if (url == null) { + throw new IllegalStateException("Could not find url for " + name); + } + final String temp = url.toString(); + final String path = temp.substring("jar:file:/".length(), temp.indexOf('!')); + return new File(path); + } +}
