Performance test and fix for logger part of the logging system

docs/administration-guide/src/main/asciidoc/logging.adoc

@@ -271,6 +271,22 @@ If you edit `logging.properties` manually on an instance managed by the node, it
 overwritten on the next synchronization with DAS.
 ====
 
+[[log-records]]
+
+=== Log Records
+
+Because the automatic detection of caller class and method from stacktrace significantly affects
+performance of the logging system, we added the `org.glassfish.main.jul.classAndMethodDetection.enabled`
+property which affects the `*.printSource` property of formatters.
+
+* 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.
+* If it is set to false, GJULE will not perform such detection. Formatters which use `getSourceClassName`
+or `getSourceMethodName` of the record will receive `null` unless the log record has set these values explicitly.
+* If the property is not set, GJULE makes the decision based on the (`*.printSource` property) - if
+any formatter requires this feature, the feature is enabled. Note that the `*.printSource` property
+must be explicitly set to true in `logging.properties`.
+* It is disabled otherwise.
 
 [[loggers]]
 

nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/GlassFishLogger.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
@@ -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);
@@ -331,6 +331,25 @@ public void logrb(final Level level, final String sourceClass, final String sour
     }
 
 
+    @Override
+    public void logrb(Level level, ResourceBundle bundle, String msg, Object... params) {
+        final GlassFishLoggingStatus status = getLoggingStatus();
+        if (!isProcessible(level, status)) {
+            return;
+        }
+        final LogRecord record = new GlassFishLogRecord(level, msg, isClassAndMethodDetectionEnabled());
+        record.setLoggerName(getName());
+        if (params != null && params.length != 0) {
+            record.setParameters(params);
+        }
+        if (bundle != null) {
+            record.setResourceBundleName(bundle.getBaseBundleName());
+            record.setResourceBundle(bundle);
+        }
+        logOrQueue(record, status);
+    }
+
+
     @Override
     public void entering(final String sourceClass, final String sourceMethod, final Object[] params) {
         final GlassFishLoggingStatus status = getLoggingStatus();
@@ -415,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;

nucleus/glassfish-jul-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,25 @@ 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 false, GJULE will not perform such detection.
+     * <p>
+     * If the property is not set, GJULE makes the decision based on the(<code>*.printSource</code>
+     * property) - if any formatter requires this feature, the feature is enabled.
+     * <p>
+     * It is disabled otherwise.
+     *
+     * @return true if formatters can use autodetected source class and method in formatters.
+     */
+    public boolean isClassAndMethodDetectionEnabled() {
+        return classAndMethodDetectionEnabled;
+    }
+
+
     /**
      * Creates clone of this instance.
      */
@@ -136,6 +159,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).
      */

nucleus/glassfish-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,24 @@ 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 false, GJULE will not perform such detection.
+     * <p>
+     * If the property is not set, GJULE makes the decision based on the (<code>*.printSource</code>
+     * property) - if any formatter requires this feature, the feature is enabled.
+     * <p>
+     * It is disabled otherwise.
+     */
+    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;
 

nucleus/glassfish-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;

nucleus/glassfish-jul-extension/src/main/java/org/glassfish/main/jul/handler/LogCollectorHandler.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
@@ -41,15 +41,29 @@ public class LogCollectorHandler extends Handler {
     private final Logger logger;
 
     /**
+     * Creates a {@link LogRecord} collector handler with the capacity of 100 records and maximal
+     * wait time 5 seconds.
+     *
      * @param loggerToFollow this handler will be added to this logger.
+     * @see LogRecordBuffer
      */
     public LogCollectorHandler(final Logger loggerToFollow) {
-        buffer = new LogRecordBuffer(100, 5);
+        this(loggerToFollow, 100, 5);
+    }
+
+    /**
+     * @param loggerToFollow this handler will be added to this logger.
+     * @param capacity capacity of the buffer.
+     * @param maxWait maximal time in seconds to wait for the free capacity. If < 1, can wait
+     *            forever.
+     * @see LogRecordBuffer
+     */
+    public LogCollectorHandler(final Logger loggerToFollow, int capacity, int maxWait) {
+        buffer = new LogRecordBuffer(capacity, maxWait);
         logger = loggerToFollow;
         logger.addHandler(this);
     }
 
-
     @Override
     public void publish(LogRecord record) {
         if (isLoggable(record)) {

nucleus/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));
     }
 
 

nucleus/glassfish-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.
      */