Port %xEx performance regression fix to main (#3154)

Author: vy

log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rewrite/MapRewritePolicyTest.java

@@ -162,7 +162,6 @@ private void checkUpdated(final Map<String, String> updatedMap) {
         assertThat("wrong size", updatedMap, hasSize(2));
     }
 
-    @SuppressWarnings("deprecation")
     private void compareLogEvents(final LogEvent orig, final LogEvent changed) {
         // Ensure that everything but the Mapped Data is still the same
         assertEquals(orig.getLoggerName(), changed.getLoggerName(), "LoggerName changed");

log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ClassResourceInfo.java

@@ -18,6 +18,7 @@
 
 import java.net.URL;
 import java.security.CodeSource;
+import java.util.function.Consumer;
 
 /**
  * Resource information (i.e., the enclosing JAR file and its version) of a class.
@@ -26,32 +27,35 @@ final class ClassResourceInfo {
 
     static final ClassResourceInfo UNKNOWN = new ClassResourceInfo();
 
-    private final String text;
+    private final Consumer<StringBuilder> renderer;
 
     final Class<?> clazz;
 
     /**
      * Constructs an instance modelling an unknown class resource.
      */
     private ClassResourceInfo() {
-        this.text = "~[?:?]";
-        this.clazz = null;
+        this.renderer = (buffer) -> buffer.append("~[?:?]");
+        clazz = null;
     }
 
     /**
      * @param clazz the class
      * @param exact {@code true}, if the class was obtained via reflection; {@code false}, otherwise
      */
     ClassResourceInfo(final Class<?> clazz, final boolean exact) {
-        this.clazz = clazz;
-        this.text = getText(clazz, exact);
-    }
-
-    private static String getText(final Class<?> clazz, final boolean exact) {
         final String exactnessPrefix = exact ? "" : "~";
         final String location = getLocation(clazz);
         final String version = getVersion(clazz);
-        return String.format("%s[%s:%s]", exactnessPrefix, location, version);
+        this.renderer = (buffer) -> {
+            buffer.append(exactnessPrefix);
+            buffer.append("[");
+            buffer.append(location);
+            buffer.append(":");
+            buffer.append(version);
+            buffer.append("]");
+        };
+        this.clazz = clazz;
     }
 
     private static String getLocation(final Class<?> clazz) {
@@ -85,8 +89,7 @@ private static String getVersion(final Class<?> clazz) {
         return "?";
     }
 
-    @Override
-    public String toString() {
-        return text;
+    void render(final StringBuilder buffer) {
+        renderer.accept(buffer);
     }
 }

log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java

@@ -210,7 +210,7 @@ public List<PatternFormatter> parse(
             list.add(new PatternFormatter(pc, field));
         }
         if (alwaysWriteExceptions && !handlesThrowable) {
-            final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, new String[0]);
+            final LogEventPatternConverter pc = ThrowablePatternConverter.newInstance(config, new String[0]);
             list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));
         }
         return list;

log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java

@@ -18,14 +18,13 @@
 
 import java.util.ArrayDeque;
 import java.util.Collections;
+import java.util.Deque;
+import java.util.HashMap;
 import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
-import java.util.Objects;
 import java.util.Queue;
 import java.util.Set;
-import java.util.stream.Collectors;
-import java.util.stream.Stream;
 import org.apache.logging.log4j.util.LoaderUtil;
 import org.apache.logging.log4j.util.StackLocatorUtil;
 
@@ -74,7 +73,7 @@ void renderStackTraceElement(
                 context.classResourceInfoByName.get(stackTraceElement.getClassName());
         if (classResourceInfo != null) {
             buffer.append(' ');
-            buffer.append(classResourceInfo);
+            classResourceInfo.render(buffer);
         }
         buffer.append(lineSeparator);
     }
@@ -102,15 +101,15 @@ private static Map<String, ClassResourceInfo> createClassResourceInfoByName(
                 final Throwable rootThrowable, final Map<Throwable, Metadata> metadataByThrowable) {
 
             // Stack trace elements of a `Throwable` only contain the class name.
-            // But we need the associated `Class<?>` to extract its resource information, i.e., JAR file and version.
+            // But we need the associated `Class` to extract its resource information, i.e., JAR file and version.
             // We are capturing the current stack to find suitable class loaders.
-            // We will use this as a bootstrap to go from a class name in a stack trace to a `Class<?>`.
-            final Map<String, ClassResourceInfo> classResourceInfoByName =
-                    StackLocatorUtil.getCurrentStackTrace().stream()
-                            .collect(Collectors.toMap(
-                                    Class::getName,
-                                    clazz -> new ClassResourceInfo(clazz, true),
-                                    (classResourceInfo1, classResourceInfo2) -> classResourceInfo1));
+            // We will use this as a bootstrap to go from a class name in a stack trace to a `Class`.
+            final Deque<Class<?>> executionStackTrace = StackLocatorUtil.getCurrentStackTrace();
+
+            // Mapping a class name to a `ClassResourceInfo` is an expensive operation.
+            // Next to `ClassResourceInfo` allocation, it requires extraction of the associated `Class`.
+            // We will use this lookup table to speed things up.
+            final Map<String, ClassResourceInfo> classResourceInfoByName = new HashMap<>();
 
             // Walk over the causal chain
             final Set<Throwable> visitedThrowables = new HashSet<>();
@@ -130,64 +129,78 @@ private static Map<String, ClassResourceInfo> createClassResourceInfoByName(
                     continue;
                 }
 
+                Class<?> executionStackTraceElementClass =
+                        executionStackTrace.isEmpty() ? null : executionStackTrace.peekLast();
                 ClassLoader lastLoader = null;
                 final StackTraceElement[] stackTraceElements = throwable.getStackTrace();
                 for (int throwableStackIndex = metadata.stackLength - 1;
                         throwableStackIndex >= 0;
                         --throwableStackIndex) {
 
-                    // Skip if the current class name is either known, or already visited and is unknown
-                    final StackTraceElement stackTraceElement = stackTraceElements[throwableStackIndex];
-                    final String stackTraceElementClassName = stackTraceElement.getClassName();
-                    ClassResourceInfo classResourceInfo = classResourceInfoByName.get(stackTraceElementClassName);
+                    // Get the exception's stack trace element
+                    final StackTraceElement throwableStackTraceElement = stackTraceElements[throwableStackIndex];
+                    final String throwableStackTraceElementClassName = throwableStackTraceElement.getClassName();
+
+                    // Skip if the current class name is already registered
+                    ClassResourceInfo classResourceInfo =
+                            classResourceInfoByName.get(throwableStackTraceElementClassName);
                     if (classResourceInfo != null) {
                         if (classResourceInfo.clazz != null) {
                             lastLoader = classResourceInfo.clazz.getClassLoader();
                         }
-                        continue;
                     }
 
-                    // Try to determine the stack trace element class, and register the result to the lookup table
-                    final Class<?> stackTraceElementClass = loadClass(lastLoader, stackTraceElementClassName);
-                    classResourceInfo = stackTraceElementClass != null
-                            ? new ClassResourceInfo(stackTraceElementClass, false)
-                            : ClassResourceInfo.UNKNOWN;
-                    classResourceInfoByName.put(stackTraceElementClassName, classResourceInfo);
+                    // See if we get a match from the execution stack trace
+                    else if (executionStackTraceElementClass != null
+                            && throwableStackTraceElementClassName.equals(executionStackTraceElementClass.getName())) {
+                        classResourceInfo = new ClassResourceInfo(executionStackTraceElementClass, true);
+                        classResourceInfoByName.put(throwableStackTraceElementClassName, classResourceInfo);
+                        lastLoader = classResourceInfo.clazz.getClassLoader();
+                        executionStackTrace.pollLast();
+                        executionStackTraceElementClass = executionStackTrace.peekLast();
+                    }
+
+                    // We don't know this class name, try to load it using the last found loader
+                    else {
+                        final Class<?> stackTraceElementClass =
+                                loadClass(lastLoader, throwableStackTraceElementClassName);
+                        classResourceInfo = stackTraceElementClass != null
+                                ? new ClassResourceInfo(stackTraceElementClass, false)
+                                : ClassResourceInfo.UNKNOWN;
+                        classResourceInfoByName.put(throwableStackTraceElementClassName, classResourceInfo);
+                    }
                 }
             }
             return classResourceInfoByName;
         }
 
-        @FunctionalInterface
-        private interface ThrowingSupplier<V> {
-
-            V supply() throws Exception;
-        }
-
         private static Class<?> loadClass(final ClassLoader loader, final String className) {
-            return Stream.<ThrowingSupplier<Class<?>>>of(
-                            // 1. Try the passed class loader
-                            () -> loader != null ? loader.loadClass(className) : null,
-                            // 2. Try the `LoaderUtil` magic
-                            () -> LoaderUtil.loadClass(className),
-                            // 3. Try the current class loader
-                            () -> ThrowableExtendedStackTraceRenderer.class
-                                    .getClassLoader()
-                                    .loadClass(className))
-                    .map(provider -> {
-                        try {
-                            final Class<?> clazz = provider.supply();
-                            if (clazz != null) {
-                                return clazz;
-                            }
-                        } catch (final Exception ignored) {
-                            // Do nothing
-                        }
-                        return null;
-                    })
-                    .filter(Objects::nonNull)
-                    .findFirst()
-                    .orElse(null);
+            for (final ClassLoadingStrategy strategy : CLASS_LOADING_STRATEGIES) {
+                try {
+                    final Class<?> clazz = strategy.run(loader, className);
+                    if (clazz != null) {
+                        return clazz;
+                    }
+                } catch (final Exception ignored) {
+                    // Do nothing
+                }
+            }
+            return null;
         }
     }
+
+    private static final ClassLoadingStrategy[] CLASS_LOADING_STRATEGIES = {
+        // 1. Try the passed class loader
+        (loader, className) -> loader != null ? loader.loadClass(className) : null,
+        // 2. Try the `LoaderUtil` magic
+        (loader, className) -> LoaderUtil.loadClass(className),
+        // 3. Try the current class loader
+        (loader, className) ->
+                ThrowableExtendedStackTraceRenderer.class.getClassLoader().loadClass(className)
+    };
+
+    private interface ClassLoadingStrategy {
+
+        Class<?> run(final ClassLoader loader, final String className) throws Exception;
+    }
 }

log4j-csv/src/main/java/org/apache/logging/log4j/csv/layout/CsvLogEventLayout.java

@@ -101,6 +101,7 @@ public String toSerializable(final LogEvent event) {
             format.print(event.getLoggerFqcn(), buffer, false);
             format.print(event.getLoggerName(), buffer, false);
             format.print(event.getMarker(), buffer, false);
+            format.print(event.getThrown(), buffer, false);
             format.print(event.getSource(), buffer, false);
             format.print(event.getContextData(), buffer, false);
             format.print(event.getContextStack(), buffer, false);

src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc

@@ -588,7 +588,7 @@ If this mode is employed without any configuration, the output will be identical
 
 `none`:: Suppress the output of the converter
 
-`short`:: Outputs the first line of the stack trace (analogous to `%ex\{1}`)
+`short`:: Outputs the first two lines of the stack trace (analogous to `%ex\{2}`)
 
 `depth`:: Outputs the first `depth` lines of the stack trace (`%ex\{0}` is analogous to `%ex\{none}`)