LOG4J2-1359 - Benchmark impact on LogEvent

log4j-api/src/main/java/org/apache/logging/log4j/util/ReflectionUtil.java

@@ -61,6 +61,7 @@ public final class ReflectionUtil {
     static {
         Method getCallerClass;
         int java7u25CompensationOffset = 0;
+        System.out.println("Using Java 7 ReflectionUtil");
         try {
             final Class<?> sunReflectionClass = LoaderUtil.loadClass("sun.reflect.Reflection");
             getCallerClass = sunReflectionClass.getDeclaredMethod("getCallerClass", int.class);

log4j-core/src/main/java/org/apache/logging/log4j/core/impl/LocationLocator.java

@@ -21,6 +21,11 @@ package org.apache.logging.log4j.core.impl;
  */
 public class LocationLocator {
 
+    static {
+        System.out.println("Using Java 7 Locator");
+    }
+
+
     public static StackTraceElement calcLocation(final String fqcnOfLogger) {
         if (fqcnOfLogger == null) {
             return null;
@@ -37,4 +42,8 @@ public class LocationLocator {
         }
         return null;
     }
+
+    public static StackTraceElement getStackTraceElement(final int depth) {
+        return new Throwable().getStackTrace()[depth];
+    }
 }
\ No newline at end of file

log4j-core/src/test/java/org/apache/logging/log4j/core/LogEventTest.java

@@ -25,7 +25,9 @@ import java.io.ObjectOutputStream;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LoggingException;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent;
+import org.apache.logging.log4j.message.Message;
 import org.apache.logging.log4j.message.SimpleMessage;
+import org.junit.BeforeClass;
 import org.junit.Ignore;
 import org.junit.Test;
 
@@ -36,6 +38,9 @@ import static org.junit.Assert.*;
  */
 public class LogEventTest {
 
+    private static Message MESSAGE = new SimpleMessage("This is a test");
+    private static TestClass TESTER = new TestClass();
+
     @Test
     public void testSerialization() throws Exception {
         final LogEvent event1 = Log4jLogEvent.newBuilder() //
@@ -147,4 +152,22 @@ public class LogEventTest {
         assertNotEquals("Events should not be equal", event1, event2);
         assertEquals("Events should be equal", event2, event3);
     }
+
+    @Test
+    public void testLocation() {
+        StackTraceElement ste = TESTER.getEventSource(this.getClass().getName());
+        assertNotNull("No StackTraceElement", ste);
+        assertEquals("Incorrect event", this.getClass().getName(), ste.getClassName());
+    }
+
+    private static class TestClass {
+        private static final String FQCN = TestClass.class.getName();
+
+        public StackTraceElement getEventSource(String loggerName) {
+            final LogEvent event = Log4jLogEvent.newBuilder().setLoggerName(loggerName)
+                    .setLoggerFqcn(FQCN).setLevel(Level.INFO).setMessage(MESSAGE).build();
+            event.setIncludeLocation(true);
+            return event.getSource();
+        }
+    }
 }

log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jpa/LogEventTest.java → log4j-core/src/test/java/org/apache/logging/log4j/core/appender/db/jpa/LogEventEntityTest.java

@@ -28,7 +28,7 @@ import org.apache.logging.log4j.message.Message;
 import org.junit.Assert;
 import org.junit.Test;
 
-public class LogEventTest {
+public class LogEventEntityTest {
 
     @Test
     public void testToImmutable_AbstractLogEventWrapperEntity() {

log4j-java9/src/main/java/org/apache/logging/log4j/core/impl/LocationLocator.java

@@ -27,4 +27,8 @@ public class LocationLocator {
     public static StackTraceElement calcLocation(final String fqcnOfLogger) {
         return walker.walk(s -> s.filter(new ClassNamePredicate(fqcnOfLogger)).findFirst()).get().toStackTraceElement();
     }
+
+    public static StackTraceElement getStackTraceElement(final int depth) {
+        return walker.walk(s -> s.skip(depth - 1)).findFirst().get().toStackTraceElement();
+    }
 }

log4j-java9/src/main/java/org/apache/logging/log4j/util/ClassNamePredicate.java

@@ -33,7 +33,6 @@ public final class ClassNamePredicate implements Predicate<StackWalker.StackFram
 
     @Override
     public boolean test(StackWalker.StackFrame f) {
-        System.out.println(f.getClassName());
         if (fqcn.equals(f.getClassName())) {
             next = true;
             return false;

log4j-java9/src/main/java/org/apache/logging/log4j/util/ReflectionUtil.java

@@ -16,7 +16,9 @@
  */
 package org.apache.logging.log4j.util;
 
-import java.util.function.Predicate;
+import java.util.List;
+import java.util.Stack;
+import java.util.stream.Collectors;
 
 /**
  * <em>Consider this class private.</em> Determines the caller's class.
@@ -36,4 +38,16 @@ public class ReflectionUtil {
     public static Class<?> getCallerClass(final Class<?> anchor) {
         return walker.walk(s -> s.filter(new ClassPredicate(anchor)).findFirst()).get().getDeclaringClass();
     }
+
+    public static Class<?> getCallerClass(final int depth) {
+        return walker.walk(s -> s.skip(depth - 1)).findFirst().get().getDeclaringClass();
+    }
+
+    public static Stack<Class<?>> getCurrentStackTrace() {
+        Stack<Class<?>> stack = new Stack<Class<?>>();
+        List<Class<?>> classes = walker.walk(s -> s.map(f -> f.getDeclaringClass()).collect(Collectors.toList()));
+        stack.addAll(classes);
+        return stack;
+    }
+
 }

log4j-perf/pom.xml

@@ -168,6 +168,9 @@
               <transformers>
                 <transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
                   <mainClass>org.openjdk.jmh.Main</mainClass>
+                  <manifestEntries>
+                    <Multi-Release>true</Multi-Release>
+                  </manifestEntries>
                 </transformer>
               </transformers>
               <filters>

log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/Log4jLogEventBenchmark.java

@@ -33,11 +33,13 @@ import org.openjdk.jmh.infra.Blackhole;
 public class Log4jLogEventBenchmark {
     private static Message MESSAGE;
     private static Throwable ERROR;
+    private static TestClass TESTER;
 
     @Setup
     public void setup() {
         MESSAGE = new SimpleMessage("Test message");
         ERROR = new Exception("test");
+        TESTER = new TestClass();
     }
 
     @Benchmark
@@ -63,10 +65,8 @@ public class Log4jLogEventBenchmark {
 
     @Benchmark
     public StackTraceElement getSourceLocationOfLogEvent() {
-        final LogEvent event = Log4jLogEvent.newBuilder().setLoggerName(this.getClass().getName())
-                .setLoggerFqcn(this.getClass().getName()).setLevel(Level.INFO).setMessage(MESSAGE).build();
-        event.setIncludeLocation(true);
-        return event.getSource();
+
+        return TESTER.getEventSource(this.getClass().getName());
     }
 
     @Benchmark
@@ -75,12 +75,29 @@ public class Log4jLogEventBenchmark {
         return Log4jLogEvent.serialize(event, false);
     }
 
+    @Benchmark
+    public Serializable createSerializableLogEventProxyWithoutExceptionWithLocation() {
+        final Log4jLogEvent event = new Log4jLogEvent("a.b.c", null, "a.b.c", Level.INFO, MESSAGE, null, null);
+        return Log4jLogEvent.serialize(event, true);
+    }
+
     @Benchmark
     public Serializable createSerializableLogEventProxyWithException(final Blackhole bh) {
         final Log4jLogEvent event = new Log4jLogEvent("a.b.c", null, "a.b.c", Level.INFO, MESSAGE, null, ERROR);
         return Log4jLogEvent.serialize(event, false);
     }
 
+    private static class TestClass {
+        private static final String FQCN = TestClass.class.getName();
+
+        public StackTraceElement getEventSource(String loggerName) {
+            final LogEvent event = Log4jLogEvent.newBuilder().setLoggerName(loggerName)
+                    .setLoggerFqcn(FQCN).setLevel(Level.INFO).setMessage(MESSAGE).build();
+            event.setIncludeLocation(true);
+            return event.getSource();
+        }
+    }
+
     // ============================== HOW TO RUN THIS TEST: ====================================
     //
     // In sampling mode (latency test):

log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ReflectionBenchmark.java

@@ -20,6 +20,7 @@ import java.lang.reflect.Constructor;
 import java.lang.reflect.InvocationTargetException;
 import java.util.Random;
 
+import org.apache.logging.log4j.core.impl.LocationLocator;
 import org.apache.logging.log4j.message.Message;
 import org.apache.logging.log4j.message.StringFormattedMessage;
 import org.apache.logging.log4j.util.ReflectionUtil;
@@ -28,7 +29,6 @@ import org.openjdk.jmh.annotations.Level;
 import org.openjdk.jmh.annotations.Scope;
 import org.openjdk.jmh.annotations.Setup;
 import org.openjdk.jmh.annotations.State;
-import sun.reflect.Reflection;
 
 /**
  * <p>
@@ -88,10 +88,6 @@ public class ReflectionBenchmark {
         return ReflectionUtil.getCallerClass(3).getName();
     }
 
-    @Benchmark
-    public String test04_getCallerClassNameSunReflection() {
-        return Reflection.getCallerClass(3).getName();
-    }
 
     @Benchmark
     public Class<?> test05_getStackTraceClassForClassName() throws ClassNotFoundException {
@@ -108,11 +104,6 @@ public class ReflectionBenchmark {
         return ReflectionUtil.getCallerClass(3);
     }
 
-    @Benchmark
-    public Class<?> test08_getDirectSunReflection() {
-        return Reflection.getCallerClass(3);
-    }
-
     @Benchmark
     public Message test09_getMessageUsingNew(final RandomInteger rng) {
         return new StringFormattedMessage("Hello %i", rng.random);
@@ -142,4 +133,45 @@ public class ReflectionBenchmark {
         return classContextManager.getClassContext();
     }
 
+
+    @Benchmark
+    public Class<?> reflectionUtilGetClass() {
+        return new ClassLocator().findClass(4);
+    }
+
+    @Benchmark
+    public String locationLocatorGetMethod() {
+        return new MethodLocator().findMethodName(4);
+    }
+
+    private static class ClassLocator {
+
+        private Class<?> findClass(int depth) {
+            if (depth == 1) {
+                return locateCaller();
+            } else {
+                return findClass(depth - 1);
+            }
+        }
+
+        private Class<?> locateCaller() {
+            return ReflectionUtil.getCallerClass(ClassLocator.class.getName());
+        }
+    }
+
+    private static class MethodLocator {
+
+        private String findMethodName(int depth) {
+            if (depth == 1) {
+                return locateMethodName();
+            } else {
+                return findMethodName(depth - 1);
+            }
+        }
+
+        private String locateMethodName() {
+            return LocationLocator.calcLocation(MethodLocator.class.getName()).getMethodName();
+        }
+    }
+
 }