Fix extended stack trace (i.e., %xEx) rendering performance regression (#3123)

alan0428a · vy · web-flow · commit 70f058daaa64 · 2024-11-02T22:00:10.000+01:00
Co-authored-by: Volkan Yazıcı &lt;volkan@yazi.ci&gt;
diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rewrite/MapRewritePolicyTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/appender/rewrite/MapRewritePolicyTest.java
@@ -163,16 +163,15 @@ 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");
         assertEquals(orig.getMarker(), changed.getMarker(), "Marker changed");
         assertEquals(orig.getLoggerFqcn(), changed.getLoggerFqcn(), "FQCN changed");
         assertEquals(orig.getLevel(), changed.getLevel(), "Level changed");
         assertArrayEquals(
-                orig.getThrown() == null ? null : orig.getThrownProxy().getExtendedStackTrace(),
-                changed.getThrown() == null ? null : changed.getThrownProxy().getExtendedStackTrace(),
+                orig.getThrown() == null ? null : orig.getThrown().getStackTrace(),
+                changed.getThrown() == null ? null : changed.getThrown().getStackTrace(),
                 "Throwable changed");
         assertEquals(orig.getContextData(), changed.getContextData(), "ContextData changed");
         assertEquals(orig.getContextStack(), changed.getContextStack(), "ContextStack changed");
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/CsvLogEventLayout.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/CsvLogEventLayout.java
@@ -95,7 +95,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.getThrownProxy(), 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);
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ClassResourceInfo.java b/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);
     }
 }
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/PatternParser.java
@@ -212,7 +212,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;
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java b/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;
+    }
 }
diff --git a/src/changelog/.2.x.x/.release-notes.adoc.ftl b/src/changelog/.2.x.x/.release-notes.adoc.ftl
@@ -35,8 +35,11 @@ See our xref:graalvm.adoc[GraalVM guide] for details.
 
 Exception handling in xref:manual/pattern-layout.adoc[Pattern Layout] went through a major rewrite.
 This effectively helped with fixing some bugs by matching the feature parity of all exception converters.
-Additionally, rendered stack traces are ensured to be prefixed with a newline, which used to be a whitespace in earlier versions.
-The support for the `\{ansi}` option in exception converters is removed too.
+Some important highlights from this rewrite:
+
+* Rendered stack traces are ensured to be prefixed with a newline, which used to be a whitespace in earlier versions.
+* Switched the default exception converter from xref:manual/pattern-layout.adoc#converter-exception-extended[the extended exception converter] to xref:manual/pattern-layout.adoc#converter-exception[the plain exception converter], which is more performant.
+* The support for the `\{ansi}` option in exception converters is removed.
 
 [#release-notes-2-25-0-instant-format]
 === Date & time formatting
diff --git a/src/changelog/.2.x.x/2691_change_PatternLayout_exception_rendering.xml b/src/changelog/.2.x.x/2691_change_PatternLayout_exception_rendering.xml
@@ -4,5 +4,6 @@
        xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
        type="changed">
   <issue id="2691" link="https://github.com/apache/logging-log4j2/pull/2691"/>
+  <issue id="3123" link="https://github.com/apache/logging-log4j2/pull/3123"/>
   <description format="asciidoc">Consolidate exception rendering logic and improve circular reference support in Pattern Layout</description>
 </entry>
diff --git a/src/changelog/.2.x.x/2691_deprecate_ThrowableProxy.xml b/src/changelog/.2.x.x/2691_deprecate_ThrowableProxy.xml
@@ -4,5 +4,6 @@
        xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
        type="deprecated">
   <issue id="2691" link="https://github.com/apache/logging-log4j2/pull/2691"/>
+  <issue id="3123" link="https://github.com/apache/logging-log4j2/pull/3123"/>
   <description format="asciidoc">Deprecate `ThrowableProxy` and all its usages</description>
 </entry>
diff --git a/src/changelog/.2.x.x/3123_change_PatternLayout_exception_renderer.xml b/src/changelog/.2.x.x/3123_change_PatternLayout_exception_renderer.xml
@@ -0,0 +1,8 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xmlns="https://logging.apache.org/xml/ns"
+       xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+       type="changed">
+  <issue id="3123" link="https://github.com/apache/logging-log4j2/pull/3123"/>
+  <description format="asciidoc">Switch the default exception converter from xref:manual/pattern-layout.adoc#converter-exception-extended[the extended exception converter] to xref:manual/pattern-layout.adoc#converter-exception[the plain exception converter]</description>
+</entry>
diff --git a/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc b/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc
@@ -624,7 +624,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}`)
 

Original file line number	Diff line number	Diff line change
`@@ -212,7 +212,7 @@ public List<PatternFormatter> parse(`
`212`	`212`	`list.add(new PatternFormatter(pc, field));`
`213`	`213`	`}`
`214`	`214`	`if (alwaysWriteExceptions && !handlesThrowable) {`
`215`		`- final LogEventPatternConverter pc = ExtendedThrowablePatternConverter.newInstance(config, new String[0]);`
	`215`	`+ final LogEventPatternConverter pc = ThrowablePatternConverter.newInstance(config, new String[0]);`
`216`	`216`	`list.add(new PatternFormatter(pc, FormattingInfo.getDefault()));`
`217`	`217`	`}`
`218`	`218`	`return list;`