Skip to content

Internal - Lazy debug/trace logging to cut string-building overhead on disabled log levels - #557

Open
cleverchuk wants to merge 1 commit into
mainfrom
cc/NH-122552
Open

Internal - Lazy debug/trace logging to cut string-building overhead on disabled log levels#557
cleverchuk wants to merge 1 commit into
mainfrom
cc/NH-122552

Conversation

@cleverchuk

Copy link
Copy Markdown
Contributor

TL;DR

Logger now supports Supplier<String>-based debug/trace calls, and call sites across
the codebase that built messages via string concatenation or String.format pass a lambda
instead 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 JMH
benchmark module quantifies the win and explains why info/warn/error/fatal were left
eager-only.

What changed

Logger gained Supplier<String> overloads for debug and trace only, backed by a
log(Level, Supplier<String>, Throwable) core method that only calls .get() after confirming
the level is enabled; a null supplier throws immediately via Objects.requireNonNull rather
than failing later in the logging pipeline. LoggerTest covers all three cases: supplier not
invoked below threshold, invoked (and message emitted) at threshold, and null rejected up
front.

Every debug/trace call site whose message was built with + concatenation or
String.format — spanning event serialization, RPC client/retry logic, host/network/cloud
metadata discovery, config loading, sampling, and transaction naming — now passes () -> ...
instead of a pre-built string. fatal/error/warn/info call 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 it
in both the guard condition and the lazy message, instead of hitting the map twice. One test
(NamingSchemeTest) has its Mockito stub changed from any() to anyString() on debug(...),
since an untyped matcher is now ambiguous between the String and Supplier<String>
overloads.

A new benchmarks Gradle module (JMH via me.champeau.jmh) benchmarks eager vs. lazy debug
calls at both a disabled and an enabled level, for both String.format and concatenation-based
messages. 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, were
not 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/catch falls back to a warn diagnostic on
that failure. That size computation is now performed eagerly, outside the lazy debug
supplier, so the exception handling still runs unconditionally regardless of the active log
level — only the message string itself is deferred.

Test services data

  1. e-1712644058766987264
  2. e-1712643928659124224
  3. e-1742334541200846848
  4. e-1777406072376840192

Copilot AI review requested due to automatic review settings July 31, 2026 20:24
@cleverchuk
cleverchuk requested review from a team as code owners July 31, 2026 20:24

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 for Logger.debug(...) and Logger.trace(...), deferring message construction until the level is enabled.
  • Updated many debug/trace call sites to use () -> ... (and snapshot locals where needed for effectively-final capture).
  • Added a new benchmarks Gradle 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:
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

2 participants