From 9ef60983f29388c3412cec609b644da58e6e5608 Mon Sep 17 00:00:00 2001 From: Jerry Shea Date: Fri, 8 Aug 2025 18:45:34 +1000 Subject: [PATCH 1/2] performance optimisation for Log4j2LoggerBackend - get log4j context direct from the logger, and reduce allocations in the common path --- .../backend/log4j2/Log4j2LogEventUtil.java | 29 ++++++++++++------- .../backend/log4j2/Log4j2LoggerBackend.java | 4 +-- 2 files changed, 20 insertions(+), 13 deletions(-) diff --git a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java index 7b33bc9c..32105866 100644 --- a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java +++ b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java @@ -37,6 +37,7 @@ import java.util.stream.Collectors; import java.util.stream.StreamSupport; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.DefaultConfiguration; @@ -59,7 +60,7 @@ final class Log4j2LogEventUtil { private Log4j2LogEventUtil() {} - static LogEvent toLog4jLogEvent(String loggerName, LogData logData) { + static LogEvent toLog4jLogEvent(Logger logger, LogData logData) { MetadataProcessor metadata = MetadataProcessor.forScopeAndLogSite(Platform.getInjectedMetadata(), logData.getMetadata()); @@ -78,7 +79,7 @@ static LogEvent toLog4jLogEvent(String loggerName, LogData logData) { * which can perhaps be installed as default if nothing else is present. Then, we would not rely * on Log4j2 internals. */ - LoggerContext ctx = LoggerContext.getContext(false); + LoggerContext ctx = logger.getContext(); Configuration config = ctx.getConfiguration(); String message; if (config instanceof DefaultConfiguration) { @@ -89,14 +90,14 @@ static LogEvent toLog4jLogEvent(String loggerName, LogData logData) { } Throwable thrown = metadata.getSingleValue(LogContext.Key.LOG_CAUSE); - return toLog4jLogEvent(loggerName, logData, message, toLog4jLevel(logData.getLevel()), thrown); + return toLog4jLogEvent(logger.getName(), logData, message, toLog4jLevel(logData.getLevel()), thrown); } - static LogEvent toLog4jLogEvent(String loggerName, RuntimeException error, LogData badData) { + static LogEvent toLog4jLogEvent(Logger logger, RuntimeException error, LogData badData) { String message = formatBadLogData(error, badData); // Re-target this log message as a warning (or above) since it indicates a real bug. Level level = badData.getLevel().intValue() < WARNING.intValue() ? WARNING : badData.getLevel(); - return toLog4jLogEvent(loggerName, badData, message, toLog4jLevel(level), error); + return toLog4jLogEvent(logger.getName(), badData, message, toLog4jLevel(level), error); } private static LogEvent toLog4jLogEvent( @@ -246,13 +247,19 @@ private static StringMap createContextMap(LogData logData) { MetadataProcessor metadataProcessor = MetadataProcessor.forScopeAndLogSite(Platform.getInjectedMetadata(), logData.getMetadata()); - StringMap contextData = ContextDataFactory.createContextData(metadataProcessor.keyCount()); - metadataProcessor.process( - HANDLER, - (key, value) -> - contextData.putValue(key, ValueQueue.maybeWrap(value, contextData.getValue(key)))); + final StringMap contextData; + // don't allocate for the common case of no keys + if (metadataProcessor.keyCount() > 0) { + contextData = ContextDataFactory.createContextData(metadataProcessor.keyCount()); + metadataProcessor.process( + HANDLER, + (key, value) -> + contextData.putValue(key, ValueQueue.maybeWrap(value, contextData.getValue(key)))); - contextData.freeze(); + contextData.freeze(); + } else { + contextData = ContextDataFactory.emptyFrozenContextData(); + } return contextData; } diff --git a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LoggerBackend.java b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LoggerBackend.java index 70a81fd5..df317cec 100644 --- a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LoggerBackend.java +++ b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LoggerBackend.java @@ -55,11 +55,11 @@ public boolean isLoggable(java.util.logging.Level level) { public void log(LogData logData) { // The caller is responsible to call isLoggable() before calling this method to ensure that only // messages above the given threshold are logged. - logger.get().log(toLog4jLogEvent(logger.getName(), logData)); + logger.get().log(toLog4jLogEvent(logger, logData)); } @Override public void handleError(RuntimeException error, LogData badData) { - logger.get().log(toLog4jLogEvent(logger.getName(), error, badData)); + logger.get().log(toLog4jLogEvent(logger, error, badData)); } } From d0c704921ddcd56f6f7d215451c026ce9e9e2e26 Mon Sep 17 00:00:00 2001 From: Jerry Shea Date: Fri, 8 Aug 2025 18:57:27 +1000 Subject: [PATCH 2/2] reduce garbage in Log4j2LoggerBackend --- .../com/google/common/flogger/LogSite.java | 12 +++++++++++ .../common/flogger/StackBasedLogSite.java | 5 +++++ .../backend/log4j2/Log4j2LogEventUtil.java | 20 +++++++++---------- 3 files changed, 26 insertions(+), 11 deletions(-) diff --git a/api/src/main/java/com/google/common/flogger/LogSite.java b/api/src/main/java/com/google/common/flogger/LogSite.java index 2a5b75dd..6d0bcd9d 100644 --- a/api/src/main/java/com/google/common/flogger/LogSite.java +++ b/api/src/main/java/com/google/common/flogger/LogSite.java @@ -104,6 +104,18 @@ public int getLineNumber() { */ public abstract @Nullable String getFileName(); + /** + * This can be overridden to allow the StackTraceElement to be cached + * @return stack trace element for this + */ + public StackTraceElement getStackTraceElement() { + return new StackTraceElement( + getClassName(), + getMethodName(), + getFileName(), + getLineNumber()); + } + // Provide a common toString() implementation for only the public attributes. @Override public final String toString() { diff --git a/api/src/main/java/com/google/common/flogger/StackBasedLogSite.java b/api/src/main/java/com/google/common/flogger/StackBasedLogSite.java index b21a37d5..c1f67781 100644 --- a/api/src/main/java/com/google/common/flogger/StackBasedLogSite.java +++ b/api/src/main/java/com/google/common/flogger/StackBasedLogSite.java @@ -67,6 +67,11 @@ public String getFileName() { return stackElement.getFileName(); } + @Override + public StackTraceElement getStackTraceElement() { + return this.stackElement; + } + @Override public boolean equals(@Nullable Object obj) { return (obj instanceof StackBasedLogSite) diff --git a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java index 32105866..e3b58afb 100644 --- a/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java +++ b/log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java @@ -21,7 +21,6 @@ import static java.util.logging.Level.WARNING; import com.google.common.flogger.LogContext; -import com.google.common.flogger.LogSite; import com.google.common.flogger.MetadataKey; import com.google.common.flogger.backend.BaseMessageFormatter; import com.google.common.flogger.backend.LogData; @@ -57,6 +56,9 @@ * documentation. */ final class Log4j2LogEventUtil { + private static final ThreadLocal newBuilder = ThreadLocal.withInitial(Log4jLogEvent::newBuilder); + private static final ThreadLocal newMutableInstant = ThreadLocal.withInitial(MutableInstant::new); + private static final ThreadLocal newStringBuilder = ThreadLocal.withInitial(StringBuilder::new); private Log4j2LogEventUtil() {} @@ -85,8 +87,10 @@ static LogEvent toLog4jLogEvent(Logger logger, LogData logData) { if (config instanceof DefaultConfiguration) { message = SimpleMessageFormatter.getDefaultFormatter().format(logData, metadata); } else { + StringBuilder sb = newStringBuilder.get(); + sb.setLength(0); message = - BaseMessageFormatter.appendFormattedMessage(logData, new StringBuilder()).toString(); + BaseMessageFormatter.appendFormattedMessage(logData, sb).toString(); } Throwable thrown = metadata.getSingleValue(LogContext.Key.LOG_CAUSE); @@ -107,15 +111,9 @@ private static LogEvent toLog4jLogEvent( org.apache.logging.log4j.Level level, Throwable thrown) { - LogSite logSite = logData.getLogSite(); - StackTraceElement locationInfo = - new StackTraceElement( - logSite.getClassName(), - logSite.getMethodName(), - logSite.getFileName(), - logSite.getLineNumber()); + StackTraceElement locationInfo = logData.getLogSite().getStackTraceElement(); - return Log4jLogEvent.newBuilder() + return newBuilder.get() .setLoggerName(loggerName) .setLoggerFqcn(logData.getLoggerName()) .setLevel(level) // this might be different from logData.getLevel() for errors. @@ -131,7 +129,7 @@ private static LogEvent toLog4jLogEvent( @SuppressWarnings({"NanosTo_Seconds", "SecondsTo_Nanos"}) private static Instant getInstant(long timestampNanos) { - MutableInstant instant = new MutableInstant(); + MutableInstant instant = newMutableInstant.get(); // Don't use Duration here as (a) it allocates and (b) we can't allow error on overflow. long epochSeconds = NANOSECONDS.toSeconds(timestampNanos); int remainingNanos = (int) (timestampNanos - SECONDS.toNanos(epochSeconds));