fix: reduce logging overhead, cache message-docs, default log level INFO - #2921
Merged
simonredfern merged 14 commits intoSep 24, 2026
Merged
simonredfern merged 14 commits into
simonredfern merged 14 commits into
Conversation
…schema cache, and default DEBUG logging
Root-caused a production incident (sustained 600% CPU, Full-GC thrashing,
eventual service timeout) on a sandbox instance. Three independent
fixes, bundled together since they trace back to the same investigation
and are small enough to review as a set.
1. MdcLoggable (code/util/Helper.scala) ran SecureLogging.maskSensitive
(~19 regex passes) and Redis-shipping JSON serialization unconditionally
on every info/warn/error/debug/trace call, before checking whether the
underlying logger or Redis would even consume the message - and, once
gated, still ran that work inline on the calling thread. On the
http4s/cats-effect request path that's often a fiber-managed worker;
non-yielding CPU-bound work there looks identical, to the runtime's own
starvation detector, to genuine blocking I/O, and its response (spinning
up compensating worker/blocker threads that are never reclaimed) links
directly to a heap dump showing hundreds of threads each holding a
private Scala-reflection symbol-table cache. Fixed by gating on
isXEnabled/RedisLogger.shouldShip (new redis_logging_min_level prop,
default INFO) and dispatching the actual work onto a small dedicated
ExecutionContext instead of the calling thread.
2. JsonSchemaGenerator.messageDocsToJsonSchema had no cache of its own,
walking every message type's field tree via Scala runtime reflection on
every call; its caller's Redis-backed cache silently falls through to a
full recompute on any Redis failure. Added an in-process memoization
(Guava-backed, no Redis dependency) alongside the existing one, using
the same pattern already proven correct by Helper.getRequiredFieldInfo.
Independent hardening for a real gap in this file - not confirmed as
this incident's cause; JsonSchemaGenerator doesn't appear anywhere in
this incident's JFR execution samples.
3. logback.xml.example sat inert (Logback only auto-loads files named
exactly logback.xml) with root level hard-coded to DEBUG; deployments
that never manually copied it over fell back to Logback's own built-in
DEBUG-to-console default. Renamed to logback.xml so it's actually
loaded, and changed the level to ${LOG_LEVEL:-INFO}: verbose logging
should be an explicit per-environment opt-in, not the default every
deployment silently pays for.
Test plan: see individual test additions (RedisLoggerShouldShipTest,
MdcLoggableDispatchTest, JsonSchemaGeneratorCacheTest,
LogbackDefaultLevelTest) plus full local suite and CI.
The endpoint rebuilt the whole response on every request, running Scala runtime reflection over every message doc example and growing the reflection universe. Cache the built response per resolved connector name with single-flight loading, a hard size bound and no caching of failures.
Reuse the store the resource-doc and swagger endpoints already use, with the same key prefix, TTL and fail-safe behaviour, so replicas and restarts share one instance's generation work. The in-process level stays in front so an unreachable Redis cannot send requests back into reflection.
The pool that runs log masking and shipping used an unbounded queue, so a burst of log calls could grow the heap. Use a bounded queue (mdc_logging_dispatch_queue_size, default 10000). When it is full, DEBUG/TRACE/INFO entries are dropped and counted while WARN/ERROR run on the calling thread. Expose the drop count and queue depth, and give the queue a short drain window on shutdown.
Warn when it is DEBUG or TRACE, since that is expensive and should only be enabled deliberately through LOG_LEVEL.
…g entries Log writes run on a dedicated pool, so the %t pattern and the Redis line format reported the pool thread instead of the request, actor or compute thread that logged. Record the caller's thread name before dispatch, lend it to the pool thread for the write, and restore the pool thread's name after.
The floor was parsed with a throwing valueOf while RedisLogger initialises, and MdcLoggable consults RedisLogger on every log call, so a mistyped value turned into failures at ordinary logging statements. Log the problem on stderr and use INFO instead.
…reation After the shutdown hook closed the dispatch pool, INFO/DEBUG/TRACE entries from other shutdown hooks were counted as dropped instead of written; write them on the calling thread since nothing is overloaded at that point. Registering the hook also threw when the first log call of the process happened during shutdown; ignore that refusal.
… thread Renaming the pool thread around every write cost two native calls per entry and made thread dumps show pool threads under request thread names. Put the caller's name in the callerThread MDC key for the duration of the write, print it after %t in the default logback pattern, and read it in the Redis line format.
The instance that generated the response returned the JValue it built, while other replicas, and the same instance after a restart, returned the form read back from Redis, so number formatting could differ between them. Return the rendered-and-parsed form on the generating instance too, and test that the first and the shared response are identical.
Call out the redis_logging_min_level default, the INFO root level, the bounded log queue, the callerThread pattern addition and the unversioned Redis key of the message-docs cache.
…anges" release_notes.md is not the place for these notes; the behaviour changes are described in the pull request instead.
ThreadPoolExecutor and ArrayBlockingQueue reject a size below 1, and the pool is created lazily on the first log call, so a 0 or negative mdc_logging_dispatch_thread_pool_size or mdc_logging_dispatch_queue_size failed that call and every later one. Use at least 1 for both.
hongwei1
changed the title
|
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
2 participants
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
Reduces the CPU and heap cost of logging and of building the
GET /obp/v2.2.0/message-docs/{connector}response. Scala runtime reflection objects are never released, so anything that runs reflection on every request makes heap usage grow with request volume. Six changes, one commit each:MdcLoggable(code/util/Helper.scala) ranSecureLogging.maskSensitive(~19 regex passes) and Redis-shipping serialization unconditionally on everyinfo/warn/error/debug/tracecall, before checking whether the underlying logger or Redis would consume the message, and then inline on the calling thread. On the http4s/cats-effect request path that is often a fiber-managed worker, where non-yielding CPU work trips the runtime's starvation detector and makes it spin up compensating threads that are never reclaimed. Now gated onisXEnabled/RedisLogger.shouldShip(newredis_logging_min_levelprop, defaultINFO), and the work is dispatched to a small dedicated pool.JsonSchemaGenerator.messageDocsToJsonSchemahad no in-process cache; its caller's Redis cache falls through to a full recompute on any Redis failure. Added a Guava-backed memoization, using the same pattern asHelper.getRequiredFieldInfo.logback.xml.examplewas inert (Logback only auto-loadslogback.xml) with the root level hard-coded toDEBUG, so deployments that never copied it fell back to Logback's built-in DEBUG. Renamed tologback.xmlwith${LOG_LEVEL:-INFO}.GET /obp/v2.2.0/message-docs/{connector}is now cached (MessageDocsJsonCache). Building the response runs reflection over every message doc example, and the result only depends on the connector'smessageDocs, which are fixed once the connector singleton is initialised.Caching.getStaticSwaggerDocCache, same key prefix,staticResourceDocsObp.cache.ttl.seconds, same fail-safe behaviour where an unreachable Redis is a miss, not an error). Key:message-docs-v2.2.0-<connector>./v5.1.0/message-docs/...reach the same v2.2.0 handler through the version bridges and are covered too.The log dispatch queue is bounded (
mdc_logging_dispatch_queue_size, default 10000; it was an unbounded queue). When it is full, DEBUG/TRACE/INFO entries are dropped and counted (Helper.mdcLogDroppedCount, first drop and then every 10000th reported on stderr) while WARN/ERROR run on the calling thread, so a warning or error is never silently lost. Queue depth is exposed asHelper.mdcLogQueueDepth, and the pool gets a 2 second drain on shutdown. Pool and queue sizes below 1 are clamped to 1.Start-up and log attribution. The effective root log level is logged at start-up (a WARN when it is DEBUG or TRACE). Asynchronously dispatched entries keep the originating thread: the caller's name is put in the
callerThreadMDC key for the duration of the write, the defaultlogback.xmlpattern prints it after%t, and the Redis line format reads it. A logback configuration of your own needs%X{callerThread}added to show it.Also: an unrecognised
redis_logging_min_levelfalls back to INFO instead of failingRedisLoggerinitialisation; entries logged by other shutdown hooks are written on the caller instead of dropped once the pool is closed; and the cached message-docs response is served in one canonical rendered form by every replica.Upgrade notes
logback.xmlships in the jar; it used to be an unusedlogback.xml.exampleat DEBUG). SetLOG_LEVEL(env var or-DLOG_LEVEL=) to change it.redis_logging_min_level(new, default INFO): withredis_logging_enabled=true, only INFO and above are shipped. Before, every level was shipped, so a deployment that already has Redis logging on stops filling the DEBUG/TRACE (and their share of the ALL) queues after upgrading, and the log-cache endpoints return nothing for those levels. Set it toTRACEto restore the old behaviour.mdc_logging_dispatch_thread_pool_size,mdc_logging_dispatch_queue_size); output from different threads is no longer strictly ordered.%X{callerThread}added to its pattern to show the thread that logged; the default one and the Redis line already have it.GET /obp/v2.2.0/message-docs/CONNECTORis cached in process and in Redis (message-docs-v2.2.0-CONNECTOR,staticResourceDocsObpTTL). The response is unchanged. The Redis copy is not versioned by build, so after an upgrade that changes message docs an existing entry can be served until its TTL passes; delete that key to refresh it at once.Local measurements
Same machine, JDK 25, H2,
-Xmx2g, 10 workers for 600 seconds, onlyGET /obp/v2.2.0/message-docs/rest_vMar2019; every response was 200.TypeConstraintobjects at endUndoPairobjects at endThe reflection object count stayed at 879 for the whole run with the cache. This measures reflection growth and latency, not CPU utilisation.
Test plan
run_tests_parallel.sh): 3937 tests, 0 failures, 0 errors, all shards passing.MessageDocsJsonCacheTest(generator call counts for repeated requests, several connectors, a concurrent cold burst, failures, restart with a warm shared level, unreachable shared level, unparsable shared entry, invalidation),MdcLoggableBoundedQueueTest(drop and count, critical entries run inline, a failing body never reaches the caller, caller-thread MDC that does not leak between tasks, writing on the caller once the pool is shut down, size clamping),RedisLoggerShouldShipTest(minimum-level parsing and fallback),MessageDocsCacheEndToEndTest(generated and shared-level responses are identical), and the updatedMdcLoggableDispatchTest.Follow-up, not in this PR: the shared message-docs cache key is not versioned by build (see the upgrade notes above).