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.
hongwei1
force-pushed
the
fix/nmb-cpu-gc-incident-combined
branch
from
September 23, 2026 20:22
9020ebf to
791875c
Compare
|
Contributor
Author
|
Closing to reopen from a cleanly-named branch (the old branch name referenced a client name that shouldn't appear in this repo's history). Same commit, same content, re-opened here. |
3 tasks
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.



Summary
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.
MdcLoggable(code/util/Helper.scala) ranSecureLogging.maskSensitive(~19 regex passes) and Redis-shipping JSON serialization unconditionally on everyinfo/warn/error/debug/tracecall, 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 onisXEnabled/RedisLogger.shouldShip(newredis_logging_min_levelprop, defaultINFO) and dispatching the actual work onto a small dedicatedExecutionContextinstead of the calling thread.JsonSchemaGenerator.messageDocsToJsonSchemahad 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 byHelper.getRequiredFieldInfo. Independent hardening for a real gap in this file -- not confirmed as this incident's cause;JsonSchemaGeneratordoesn't appear anywhere in this incident's JFR execution samples.logback.xml.examplesat inert (Logback only auto-loads files named exactlylogback.xml) with root level hard-coded toDEBUG; deployments that never manually copied it over fell back to Logback's own built-in DEBUG-to-console default. Renamed tologback.xmlso 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
mvn -pl obp-commons,obp-api -am compile -DskipTests -o-- BUILD SUCCESSRedisLoggerShouldShipTest,MdcLoggableDispatchTest,JsonSchemaGeneratorCacheTest,MessageDocsJsonSchemaTest,LogbackDefaultLevelTest-- all passing individuallyrun_tests_parallel.sh), run twice -- 3919 tests / 0 failures / 0 errors / 18 skipped, all shards passing