Internal - Lazy debug/trace logging to cut string-building overhead on disabled log levels - #557
Open
cleverchuk wants to merge 1 commit into
Open
Internal - Lazy debug/trace logging to cut string-building overhead on disabled log levels#557cleverchuk wants to merge 1 commit into
cleverchuk wants to merge 1 commit into
Conversation
Contributor
There was a problem hiding this comment.
Pull request overview
This PR adds lazy (supplier-based) message evaluation for debug/trace logging in libs/logging, updates a broad set of call sites to pass lambdas instead of eagerly-built strings, and introduces a new benchmarks module to quantify the overhead tradeoffs with JMH.
Changes:
- Added
Supplier<String>overloads forLogger.debug(...)andLogger.trace(...), deferring message construction until the level is enabled. - Updated many
debug/tracecall sites to use() -> ...(and snapshot locals where needed for effectively-final capture). - Added a new
benchmarksGradle module with a JMH benchmark and documentation for running it.
Reviewed changes
Copilot reviewed 46 out of 46 changed files in this pull request and generated 3 comments.
Show a summary per file
| File | Description |
|---|---|
| settings.gradle.kts | Includes the new benchmarks module in the Gradle build. |
| libs/shared/src/test/java/com/solarwinds/opentelemetry/extensions/NamingSchemeTest.java | Adjusts Mockito matcher to disambiguate debug(String) vs debug(Supplier<String>). |
| libs/shared/src/main/java/com/solarwinds/opentelemetry/extensions/TransactionNameManager.java | Converts trace/debug message building to lazy suppliers. |
| libs/shared/src/main/java/com/solarwinds/opentelemetry/extensions/SolarwindsSampler.java | Converts trace message building to lazy suppliers (with local snapshot). |
| libs/shared/src/main/java/com/solarwinds/opentelemetry/extensions/ResourceCustomizer.java | Converts debug message building to lazy suppliers. |
| libs/shared/src/main/java/com/solarwinds/opentelemetry/extensions/config/JsonSettingWrapper.java | Converts debug message building to lazy suppliers. |
| libs/sampling/src/main/java/com/solarwinds/joboe/sampling/XtraceOptions.java | Converts debug message building to lazy suppliers (with local snapshot for loop entry). |
| libs/sampling/src/main/java/com/solarwinds/joboe/sampling/TraceDecisionUtil.java | Converts debug message building to lazy suppliers. |
| libs/sampling/src/main/java/com/solarwinds/joboe/sampling/Metadata.java | Converts debug message building to lazy suppliers. |
| libs/logging/src/test/java/com/solarwinds/joboe/logging/LoggerTest.java | Adds tests for lazy debug(Supplier<String>) behavior and null-supplier rejection. |
| libs/logging/src/main/java/com/solarwinds/joboe/logging/Logger.java | Adds Supplier<String> overloads for debug/trace and a supplier-backed logging path. |
| libs/logging/src/main/java/com/solarwinds/joboe/logging/FileLoggerStream.java | Converts debug message building to lazy suppliers (including exception messages). |
| libs/lambda/src/main/java/com/solarwinds/opentelemetry/extensions/FileSettingsReader.java | Converts debug message building to lazy suppliers. |
| libs/lambda/src/main/java/com/solarwinds/opentelemetry/extensions/AwsLambdaSettingsFetcher.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/UamsClientIdReader.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/TimeUtils.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/ServerHostInfoReader.java | Converts debug message building to lazy suppliers across host/network metadata logic. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/HostInfoUtils.java | Converts debug message building to lazy suppliers in provider discovery. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/ExecUtils.java | Converts debug message building to lazy suppliers for stderr output. |
| libs/core/src/main/java/com/solarwinds/joboe/core/util/BackTraceUtil.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/TestReporter.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/settings/RpcSettingsReader.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/settings/PollingSettingsFetcher.java | Converts debug message building to lazy suppliers (including interruption message). |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/RpcSettings.java | Converts debug message building to lazy suppliers in arg parsing and flags conversion. |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/RpcClient.java | Converts debug message building to lazy suppliers in retry/init paths (with snapshot for delay). |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/KeepAliveMonitor.java | Converts debug message building to lazy suppliers for ping failures. |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/grpc/GrpcClient.java | Converts debug message building to lazy suppliers for batch posting and compression info. |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/ClientManagerProvider.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/rpc/ClientLoggingCallback.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/QueuingEventReporter.java | Converts debug message building to lazy suppliers (interval, failures, shutdown). |
| libs/core/src/main/java/com/solarwinds/joboe/core/profiler/Profiler.java | Converts debug message building to lazy suppliers (startup, interruption, profiling events). |
| libs/core/src/main/java/com/solarwinds/joboe/core/NonThreadLocalTestReporter.java | Converts debug message building to lazy suppliers. |
| libs/core/src/main/java/com/solarwinds/joboe/core/EventValueConverter.java | Converts debug message building to lazy suppliers for converter fallback. |
| libs/core/src/main/java/com/solarwinds/joboe/core/EventImpl.java | Converts debug/trace message building to lazy suppliers; moves BSON-size computation eager while keeping message lazy. |
| libs/config/src/main/java/com/solarwinds/joboe/config/ConfigManager.java | Converts debug message building to lazy suppliers for uninitialized config cases. |
| libs/config/src/main/java/com/solarwinds/joboe/config/ConfigContainer.java | Avoids double map lookups and converts duplicate-key debug message to lazy supplier. |
| instrumentation/instrumentation-shared/src/main/java/com/solarwinds/opentelemetry/instrumentation/StatementTruncator.java | Converts debug message building to lazy suppliers (with snapshot length). |
| custom/src/test/java/com/solarwinds/opentelemetry/extensions/SolarwindsProfilingSpanProcessorTest.java | Removes unused stubs after logging changes (test cleanup). |
| custom/src/main/java/com/solarwinds/opentelemetry/extensions/SolarwindsProfilingSpanProcessor.java | Converts debug message building to lazy suppliers. |
| custom/src/main/java/com/solarwinds/opentelemetry/extensions/SolarwindsAgentListener.java | Converts debug message building to lazy suppliers for startup diagnostics. |
| custom/src/main/java/com/solarwinds/opentelemetry/extensions/config/HttpSettingsReader.java | Converts debug message building to lazy suppliers. |
| custom/src/main/java/com/solarwinds/opentelemetry/extensions/config/ConfigurationLoader.java | Converts debug message building to lazy suppliers for masked service key logging. |
| bootstrap/src/main/java/com/solarwinds/opentelemetry/core/Util.java | Converts debug message building to lazy suppliers for URL parse failures. |
| benchmarks/src/jmh/java/com/solarwinds/benchmarks/LoggerLazyLoggingBenchmark.java | Adds a JMH benchmark comparing eager vs lazy debug message construction. |
| benchmarks/README.md | Documents how to run and extend benchmarks. |
| benchmarks/build.gradle.kts | Configures the benchmarks module with the JMH plugin and dependencies. |
Suppressed comments (1)
libs/logging/src/main/java/com/solarwinds/joboe/logging/Logger.java:192
- Same concern as the 2-arg Supplier overload: keeping the Supplier-based core log(Level, Supplier, Throwable) method non-public avoids exposing lazy logging for other levels and avoids introducing an additional public overload pair for log(…) that can make null arguments ambiguous at call sites.
Comment on lines
+183
to
+185
| public void log(Level level, Supplier<String> messageSupplier) { | ||
| log(level, messageSupplier, null); | ||
| } |
Comment on lines
+282
to
+286
| @Test | ||
| public void testLazyMessageNotEvaluatedWhenBelowLevel() throws Exception { | ||
| Logger logger = new Logger(); | ||
| logger.configure( | ||
| LoggerConfiguration.builder().logSetting(getLogSetting(Logger.Level.INFO)).build()); |
| /** | ||
| * Compares eager {@code debug(String)} against lazy {@code debug(Supplier<String>)} logging. | ||
| * | ||
| * <p>Four scenarios are driven by the {@link #loggerLevel} parameter: |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
TL;DR
Loggernow supportsSupplier<String>-baseddebug/tracecalls, and call sites acrossthe codebase that built messages via string concatenation or
String.formatpass a lambdainstead of a pre-built string. Message construction is skipped entirely when the level is
disabled, which is the common case in production (default level is
INFO). A new JMHbenchmark module quantifies the win and explains why
info/warn/error/fatalwere lefteager-only.
What changed
LoggergainedSupplier<String>overloads fordebugandtraceonly, backed by alog(Level, Supplier<String>, Throwable)core method that only calls.get()after confirmingthe level is enabled; a null supplier throws immediately via
Objects.requireNonNullratherthan failing later in the logging pipeline.
LoggerTestcovers all three cases: supplier notinvoked below threshold, invoked (and message emitted) at threshold, and null rejected up
front.
Every
debug/tracecall site whose message was built with+concatenation orString.format— spanning event serialization, RPC client/retry logic, host/network/cloudmetadata discovery, config loading, sampling, and transaction naming — now passes
() -> ...instead of a pre-built string.
fatal/error/warn/infocall sites were left untouched,since those levels didn't get lazy overloads (rationale below).
A few call sites needed a small adjustment to satisfy Java's effectively-final capture rule for
lambdas: loop variables that get reassigned, and locals whose value changes later in the same
method, are snapshotted into a dedicated final variable at the point of logging.
ConfigContainer's duplicate-key logging now reads the existing map value once and reuses itin both the guard condition and the lazy message, instead of hitting the map twice. One test
(
NamingSchemeTest) has its Mockito stub changed fromany()toanyString()ondebug(...),since an untyped matcher is now ambiguous between the
StringandSupplier<String>overloads.
A new
benchmarksGradle module (JMH viame.champeau.jmh) benchmarks eager vs. lazydebugcalls at both a disabled and an enabled level, for both
String.formatand concatenation-basedmessages. The disabled case is where lazy logging wins: the eager call still builds and
discards the message, while the lazy supplier is never invoked. The enabled case measures the
opposite — the lambda-allocation overhead lazy logging adds once the work can't be skipped —
which is why
info/warn/error/fatal, being effectively always-enabled in practice, werenot given lazy overloads.
One call site's message estimated an entry's BSON-encoded size, a computation that can throw
for unrecognized value types; the surrounding
try/catchfalls back to awarndiagnostic onthat failure. That size computation is now performed eagerly, outside the lazy
debugsupplier, so the exception handling still runs unconditionally regardless of the active log
level — only the message string itself is deferred.
Test services data