Fix JulLogger CPU burn from unconditional stack-trace walk (#1511)#1515
Open
msrathore-db wants to merge 1 commit into
Open
Fix JulLogger CPU burn from unconditional stack-trace walk (#1511)#1515msrathore-db wants to merge 1 commit into
msrathore-db wants to merge 1 commit into
Conversation
JulLogger.log() called getCaller() — which walks the full thread stack
via Thread.currentThread().getStackTrace() — before checking whether the
level was loggable, and the {}-format overloads ran String.format()
eagerly. DatabricksArray logs once per element during type conversion,
so reading array/complex-type columns paid for a full stack walk per
element even at the default INFO level where those records are discarded,
dominating reader-thread CPU.
Short-circuit on logger.isLoggable(level) before getCaller(), and guard
each {}-format overload behind the matching isLoggable check so disabled
levels do no formatting work. Behavior is unchanged (JUL discards those
records anyway); a 5M-element disabled-level trace loop drops from
~4,170 ms to ~4 ms of CPU.
Co-authored-by: Isaac
Signed-off-by: Madhavendra Rathore <madhavendra.rathore@databricks.com>
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
1 participant
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.
Summary
Fixes #1511.
JulLogger.log()calledgetCaller()— which walks the full thread stack viaThread.currentThread().getStackTrace()— before checking whether the level was loggable, and the{}-format overloads ranString.format()eagerly.DatabricksArraylogs once per element during type conversion, so reading array/complex-type columns paid for a full stack walk per element even at the default INFO level (where FINEST/FINE records are discarded), dominating JDBC reader-thread CPU.Change
log()short-circuits onlogger.isLoggable(level)before invoking thegetCaller()stack walk.{}-format overload (trace/debug/info/warn/error) guardsString.format(...)behind the matchingisLoggable(...)check, so disabled levels do no formatting work.Behavior is unchanged — JUL discards those records anyway; only the wasted work is removed.
Repro / measurement
A 5M-element loop simulating per-element trace logging with the driver logger at INFO, run against the compiled driver on an identical classpath:
Tests
testNoLoggingWhenLevelDisabledandtestFormatVariantsSkipFormattingWhenLevelDisabled(the latter uses an explodingtoString()argument to prove the format path is skipped when the level is disabled).JulLoggerTestsetUp to stubisLoggable → trueso existing verify-based tests still exercise the logging path.JulLoggerTest18/18 andDatabricksArrayTest/Slf4jLoggerTest/JdbcLoggerFactoryTest43/43 pass;spotless:checkpasses.NO_CHANGELOG=true
This pull request and its description were written by Isaac.