Resolved performance issues

- The stacktrace analysis is now done just when - it is detected that some handler/formatter uses its results - it is explicitly enabled Signed-off-by: David Matějček <david.matejcek@omnifish.ee>
eclipse-ee4j · May 10, 2024 · 86c9abc · 86c9abc
1 parent 8a16b27
commit 86c9abc
Show file tree

Hide file tree

Showing 14 changed files with 147 additions and 67 deletions.
diff --git a/nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/GlassFishLogger.java b/nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/GlassFishLogger.java
@@ -157,7 +157,7 @@ public void log(final Level level, final String msg) {
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msg);
+        final LogRecord record = new GlassFishLogRecord(level, msg, isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         record.setResourceBundle(getResourceBundle());
         record.setResourceBundleName(getResourceBundleName());
@@ -171,7 +171,7 @@ public void log(final Level level, final Supplier<String> msgSupplier) {
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msgSupplier.get());
+        final LogRecord record = new GlassFishLogRecord(level, msgSupplier.get(), isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         logOrQueue(record, status);
     }
@@ -189,7 +189,7 @@ public void log(final Level level, final String msg, final Object[] params) {
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msg);
+        final LogRecord record = new GlassFishLogRecord(level, msg, isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         record.setResourceBundle(getResourceBundle());
         record.setResourceBundleName(getResourceBundleName());
@@ -204,7 +204,7 @@ public void log(final Level level, final String msg, final Throwable thrown) {
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msg);
+        final LogRecord record = new GlassFishLogRecord(level, msg, isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         record.setResourceBundle(getResourceBundle());
         record.setResourceBundleName(getResourceBundleName());
@@ -219,7 +219,7 @@ public void log(final Level level, final Throwable thrown, final Supplier<String
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msgSupplier.get());
+        final LogRecord record = new GlassFishLogRecord(level, msgSupplier.get(), isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         record.setThrown(thrown);
         logOrQueue(record, status);
@@ -337,7 +337,7 @@ public void logrb(Level level, ResourceBundle bundle, String msg, Object... para
         if (!isProcessible(level, status)) {
             return;
         }
-        final LogRecord record = new GlassFishLogRecord(level, msg);
+        final LogRecord record = new GlassFishLogRecord(level, msg, isClassAndMethodDetectionEnabled());
         record.setLoggerName(getName());
         if (params != null && params.length != 0) {
             record.setParameters(params);
@@ -434,6 +434,12 @@ private boolean isToQueue(final GlassFishLoggingStatus status) {
     }
 
 
+    private boolean isClassAndMethodDetectionEnabled() {
+        final GlassFishLogManager manager = GlassFishLogManager.getLogManager();
+        return manager == null ? false : manager.getConfiguration().isClassAndMethodDetectionEnabled();
+    }
+
+
     void checkAndLog(final LogRecord record) {
         if (!isLoggableLevel(record.getLevel())) {
             return;

diff --git a/...-extension/src/main/java/org/glassfish/main/jul/cfg/GlassFishLogManagerConfiguration.java b/...-extension/src/main/java/org/glassfish/main/jul/cfg/GlassFishLogManagerConfiguration.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -27,6 +27,8 @@
 
 import org.glassfish.main.jul.tracing.GlassFishLoggingTracer;
 
+import static org.glassfish.main.jul.cfg.GlassFishLoggingConstants.KEY_CLASS_AND_METHOD_DETECTION_ENABLED;
+import static org.glassfish.main.jul.cfg.GlassFishLoggingConstants.KEY_FORMATTER_PRINT_SOURCE_SUFFIX;
 import static org.glassfish.main.jul.cfg.GlassFishLoggingConstants.KEY_TRACING_ENABLED;
 
 /**
@@ -39,13 +41,15 @@ public class GlassFishLogManagerConfiguration implements Serializable, Cloneable
     private static final long serialVersionUID = 1L;
     private final LoggingProperties properties;
     private final boolean tracingEnabled;
+    private final boolean classAndMethodDetectionEnabled;
 
     /**
      * @param properties configuration to clone
      */
     public GlassFishLogManagerConfiguration(final LoggingProperties properties) {
         this.properties = properties.clone();
         this.tracingEnabled = Boolean.parseBoolean(this.properties.getProperty(KEY_TRACING_ENABLED));
+        this.classAndMethodDetectionEnabled = resolveClassAndMethodDetectionEnabled(this.properties);
     }
 
 
@@ -91,6 +95,24 @@ public boolean isTracingEnabled() {
     }
 
 
+    /**
+     * If {@link GlassFishLoggingConstants#KEY_CLASS_AND_METHOD_DETECTION_ENABLED} is set to true,
+     * GJULE will detect the caller class and method from stacktrace,
+     * which is quite expensive operation affecting logging throughput.
+     * <p>
+     * If it is set to null, GJULE will not perform such detection.
+     * <p>
+     * If the property is not set, GJULE makes the decision based on known handlers
+     * (<code>*.printSource</code> value) - if any handler requires this feature, it is enabled.
+     * It is disabled otherwise or you can forcibly enable it by setting the value to true or false.
+     *
+     * @return true if handlers can use source class and method in formatters.
+     */
+    public boolean isClassAndMethodDetectionEnabled() {
+        return classAndMethodDetectionEnabled;
+    }
+
+
     /**
      * Creates clone of this instance.
      */
@@ -136,6 +158,21 @@ public static GlassFishLogManagerConfiguration parse(final InputStream inputStre
     }
 
 
+    private static boolean resolveClassAndMethodDetectionEnabled(final LoggingProperties properties) {
+        String value = properties.getProperty(KEY_CLASS_AND_METHOD_DETECTION_ENABLED);
+        if (Boolean.TRUE.toString().equalsIgnoreCase(value)) {
+            return true;
+        }
+        if (Boolean.FALSE.toString().equalsIgnoreCase(value)) {
+            return false;
+        }
+        return properties.stringPropertyNames().stream()
+            .filter(name -> name.endsWith(KEY_FORMATTER_PRINT_SOURCE_SUFFIX))
+            .anyMatch(name -> properties.getProperty(name, Boolean.FALSE.toString())
+                .equalsIgnoreCase(Boolean.TRUE.toString()));
+    }
+
+
     /**
      * Configuration entry, pair of a key and a value, both can be null (but it is not very useful).
      */

diff --git a/...ish-jul-extension/src/main/java/org/glassfish/main/jul/cfg/GlassFishLoggingConstants.java b/...ish-jul-extension/src/main/java/org/glassfish/main/jul/cfg/GlassFishLoggingConstants.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -16,6 +16,7 @@
 
 package org.glassfish.main.jul.cfg;
 
+import java.util.logging.LogRecord;
 
 /**
  * Constants used to configure the Java Util Logging.
@@ -67,6 +68,23 @@ public class GlassFishLoggingConstants {
     /** If this key is set to true, GJULE will print really detailed tracing info to the standard output */
     public static final String KEY_TRACING_ENABLED = "org.glassfish.main.jul.tracing.enabled";
 
+    /**
+     * If this key is set to true, GJULE will detect the caller class and method from stacktrace,
+     * which is quite expensive operation affecting logging throughput.
+     * <p>
+     * If it is set to null, GJULE will not perform such detection.
+     * <p>
+     * If the property is not set, GJULE makes the decision based on known handlers
+     * (<code>*.printSource</code> value) - if any handler requires this feature, it is enabled.
+     * It is disabled otherwise or you can forcibly enable it by setting the value to true or false.
+     */
+    public static final String KEY_CLASS_AND_METHOD_DETECTION_ENABLED = "org.glassfish.main.jul.classAndMethodDetection.enabled";
+    /**
+     * Enable printing the source class and method of the LogRecord.
+     * See {@link LogRecord#getSourceClassName()} and {@link LogRecord#getSourceMethodName()}
+     */
+    public static final String KEY_FORMATTER_PRINT_SOURCE_SUFFIX = "printSource";
+
     /** 1 000 000 */
     public static final long BYTES_PER_MEGABYTES = 1_000_000;
 

diff --git a/...h-jul-extension/src/main/java/org/glassfish/main/jul/formatter/GlassFishLogFormatter.java b/...h-jul-extension/src/main/java/org/glassfish/main/jul/formatter/GlassFishLogFormatter.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -31,6 +31,7 @@
 import static java.time.temporal.ChronoField.MINUTE_OF_HOUR;
 import static java.time.temporal.ChronoField.NANO_OF_SECOND;
 import static java.time.temporal.ChronoField.SECOND_OF_MINUTE;
+import static org.glassfish.main.jul.cfg.GlassFishLoggingConstants.KEY_FORMATTER_PRINT_SOURCE_SUFFIX;
 import static org.glassfish.main.jul.formatter.GlassFishLogFormatter.GlassFishLogFormatterProperty.PRINT_SEQUENCE_NUMBER;
 import static org.glassfish.main.jul.formatter.GlassFishLogFormatter.GlassFishLogFormatterProperty.PRINT_SOURCE;
 import static org.glassfish.main.jul.formatter.GlassFishLogFormatter.GlassFishLogFormatterProperty.TIMESTAMP_FORMAT;
@@ -249,7 +250,7 @@ public enum GlassFishLogFormatterProperty implements LogProperty {
          * Enable printing the source class and method of the LogRecord.
          * See {@link LogRecord#getSourceClassName()} and {@link LogRecord#getSourceMethodName()}
          */
-        PRINT_SOURCE("printSource"),
+        PRINT_SOURCE(KEY_FORMATTER_PRINT_SOURCE_SUFFIX),
         ;
 
         private final String propertyName;

diff --git a/...glassfish-jul-extension/src/main/java/org/glassfish/main/jul/handler/LogRecordBuffer.java b/...glassfish-jul-extension/src/main/java/org/glassfish/main/jul/handler/LogRecordBuffer.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -144,7 +144,7 @@ private void addWithTimeout(final GlassFishLogRecord record) {
             this + ": The buffer was forcibly cleared after " + maxWait + " s timeout for adding another log record." //
                 + " Log records were lost." //
                 + " It might be caused by a recursive deadlock," //
-                + " you can increase the capacity or the timeout to avoid this."));
+                + " you can increase the capacity or the timeout to avoid this.", false));
     }
 
 

diff --git a/...sfish-jul-extension/src/main/java/org/glassfish/main/jul/handler/LoggingOutputStream.java b/...sfish-jul-extension/src/main/java/org/glassfish/main/jul/handler/LoggingOutputStream.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -24,6 +24,7 @@
 import java.util.logging.LogRecord;
 import java.util.logging.Logger;
 
+import org.glassfish.main.jul.GlassFishLogManager;
 import org.glassfish.main.jul.record.GlassFishLogRecord;
 
 
@@ -68,10 +69,10 @@ void addRecord(final Throwable throwable) {
         if (closed.get()) {
             return;
         }
-        final GlassFishLogRecord logRecord = new GlassFishLogRecord(logRecordLevel, "");
-        logRecord.setThrown(throwable);
-        logRecord.setLoggerName(this.loggerName);
-        logRecordBuffer.add(logRecord);
+        final GlassFishLogRecord record = new GlassFishLogRecord(logRecordLevel, "", isSourceDetectionEnabled());
+        record.setThrown(throwable);
+        record.setLoggerName(this.loggerName);
+        logRecordBuffer.add(record);
     }
 
 
@@ -86,14 +87,14 @@ public void flush() throws IOException {
         if (closed.get()) {
             return;
         }
-        final String logMessage = getMessage();
-        if (logMessage.isEmpty() || lineSeparator.equals(logMessage)) {
+        final String message = getMessage();
+        if (message.isEmpty() || lineSeparator.equals(message)) {
             // avoid empty records
             return;
         }
-        final GlassFishLogRecord logRecord = new GlassFishLogRecord(logRecordLevel, logMessage);
-        logRecord.setLoggerName(this.loggerName);
-        logRecordBuffer.add(logRecord);
+        final GlassFishLogRecord record = new GlassFishLogRecord(logRecordLevel, message, isSourceDetectionEnabled());
+        record.setLoggerName(this.loggerName);
+        logRecordBuffer.add(record);
     }
 
     private synchronized String getMessage() throws IOException {
@@ -104,6 +105,12 @@ private synchronized String getMessage() throws IOException {
     }
 
 
+    private boolean isSourceDetectionEnabled() {
+        final GlassFishLogManager manager = GlassFishLogManager.getLogManager();
+        return manager == null ? false : manager.getConfiguration().isClassAndMethodDetectionEnabled();
+    }
+
+
     /**
      * Shutdown the internal logging pump.
      */

diff --git a/...assfish-jul-extension/src/main/java/org/glassfish/main/jul/record/GlassFishLogRecord.java b/...assfish-jul-extension/src/main/java/org/glassfish/main/jul/record/GlassFishLogRecord.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2022 Eclipse Foundation and/or its affiliates. All rights reserved.
+ * Copyright (c) 2022, 2024 Eclipse Foundation and/or its affiliates. All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v. 2.0, which is available at
@@ -42,16 +42,6 @@ public class GlassFishLogRecord extends LogRecord {
     private final String threadName;
     private String messageKey;
 
-    /**
-     * Creates new record. Source class and method will be autodetected.
-     *
-     * @param level
-     * @param message
-     */
-    public GlassFishLogRecord(final Level level, final String message) {
-        this(new LogRecord(level, message), true);
-    }
-
 
     /**
      * Creates new record. Source class and method will be autodetected now or set after this
@@ -298,23 +288,21 @@ public String toString() {
     }
 
 
-    private boolean detectClassAndMethod(final LogRecord wrappedRecord) {
-        final StackTraceElement[] stack = new Throwable().getStackTrace();
-        boolean found = false;
+    private void detectClassAndMethod(final LogRecord wrappedRecord) {
+        final StackTraceElement[] stack = Thread.currentThread().getStackTrace();
+        boolean ignoredClass = false;
         for (final StackTraceElement element : stack) {
             final String className = element.getClassName();
-            if (!found) {
-                found = isIgnoredStackTraceElement(className);
+            if (!ignoredClass) {
+                ignoredClass = isIgnoredStackTraceElement(className);
                 continue;
             }
             if (!isIgnoredStackTraceElement(className)) {
                 wrappedRecord.setSourceClassName(className);
                 wrappedRecord.setSourceMethodName(element.getMethodName());
-                return true;
+                return;
             }
         }
-        // don't try it again.
-        return true;
     }