[2/2] logging-log4j2 git commit: LOG4J2-1295 Added automated GC-free test. Still @Ignored as of now because the API creates vararg arrays so the test fails.

[rp...@apache.org]

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/master
Commit: 52d04e0779eef09d0826c800cdc0874eea4960e5
Parents: 575cd5b
Author: rpopma <rp...@apache.org>
Authored: Tue Mar 15 17:25:40 2016 +1100
Committer: rpopma <rp...@apache.org>
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);
+    }
+}