fix(core) #155: stop the "Max loading factor steps reached" WARN on every control loop pass - #201
fix(core) #155: stop the "Max loading factor steps reached" WARN on every control loop pass#201astubbs wants to merge 6 commits into
Conversation
…very control loop pass
checkPipelinePressure() runs on every control loop pass and logged
"isPoolQueueLow(): Max loading factor steps reached: {}/{}" at WARN with no rate
limiting whenever DynamicLoadFactor#isMaxReached() held. Two configurations reach
that state, and both spam the log for as long as the queue sits below target:
- a dynamic factor that has stepped up to its cap (the reported 100/100) - the
condition is then permanent, so the line repeats for the life of the process;
- a FIXED factor - PCModule#initDynamicLoadFactor() builds DynamicLoadFactor(n, n)
when messageBufferSize is set, so isMaxReached() is true from construction and the
WARN fires from the very first pass. Following the README's own PARTITION-ordering
tuning advice therefore earns permanent log noise saying nothing is wrong. Nobody
had reported that half; it fell out of reading the code for the reported one.
The reporting changes; the buffering does not. The factor, the queue target and the
step-up rules are untouched.
DynamicLoadFactor now knows whether it is fixed (isStaticFactor(): it starts at its
own ceiling, via messageBufferSize or initialLoadFactor == maximumLoadFactor). Such a
factor cannot step, so maybeStepUp() short-circuits rather than running the
warm-up/cool-down checks, and the ceiling is reported at debug - the user asked for a
fixed buffer and got one, which is not a warning. PCModule says so through a new
DynamicLoadFactor.fixedAt(n) factory.
A DYNAMIC factor at its cap still warns: it means the in-flight target will not grow
any further, which a user may want to act on. Demoting it would fix the volume by
throwing away the signal. Instead it is rate limited to once per 30s with the
existing RateLimiter (as BrokerPollSystem and ProcessingShard already do) and reworded
to read as saturation - naming maximumLoadFactor/messageBufferSize as the thing to
change - rather than as a failure.
LoadFactorCeilingReportingTest drives the real pressure-check pass 500 times through
TestParallelEoSStreamProcessor with the load factor wired through PCModule, and
asserts on captured log output. Verified red before the fix: 500 warnings in the fixed
case (where zero is now correct) and 500 in the dynamic case (where 1 is now correct).
The stall in the original report is a different defect, fixed upstream (confluentinc#547/confluentinc#606) and
further in the confluentinc#857 family here (#119). This changes only what is logged.
Upstream-Issue: confluentinc#402
Forwarded: not-needed
Applied-Upstream: no
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
…ise entry The manifest is the source of truth for the fork side too, so the entry advances at the transition that causes it - opening the PR - not at merge time. Upstream-Issue: confluentinc#402 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
Dependency Review✅ No vulnerabilities or license issues or OpenSSF Scorecard issues found.Scanned FilesNone |
|
Claude Code is working… I'll analyze this and get back to you. |
✅ Duplicate Code ReportTwo engines run in parallel for cross-validation. Each has its own thresholds tuned to its baseline - the real safety net is the per-engine "max increase vs base" check. ✅ PMD CPD
No new clones introduced by this PR. ✅ jscpd (language-agnostic)
No new clones introduced by this PR. Powered by astubbs/duplicate-code-cross-check |
|
Claude finished @astubbs's task in 6m 0s —— View job Claude's review of PR #201Todo list
SummaryThe mechanism, fix design, and rationale in the PR description all check out against the code. I ran Finding: the new messages report the wrong "target" number
I confirmed this is a real discrepancy, not just a theoretical one, by instrumenting the actual test run:
Given the entire point of this PR is to make these messages trustworthy and non-confusing (the PR body specifically frames the WARN as something that should "read as saturation ... and name what to change"), a "target" number that's off by a factor of 2-100x from what the code actually checked undercuts that goal — a user comparing the logged numbers against Everything else checked out
No blocking issues beyond the message-content bug above — it's a reporting-only defect (no functional/behavioral risk) but worth fixing before merge since it's the exact kind of confusing-log-content this PR sets out to eliminate. |
✅ SpotBugs ReportNo bugs found (new bugs only — baseline from base branch excluded). |
…constraint in the ledger Both were only in the PR body, which is not where a future session looks. The duplicate-code gate cannot catch the LogCapture collision with #201 - it diffs each PR against master, and neither copy is on master yet - so the "whichever merges second drops its copy" resolution has to be written down. Also records why UserFunctionFailureLoggingTest is @isolated, and which two shutdown tests go intermittent if that is ever removed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
…ared Review found the new ceiling messages printing getQueueTargetLoaded() (in-flight target x loading factor) as the target the executor pool queue was "below", when the branch is entered by isPoolQueueLow() comparing the queue against the un-multiplied getPoolLoadTarget(). In the fixed-factor case that reported "0 queued vs 1008" for a check that actually tested "0 vs 16" - 63x out, in the exact messages this PR exists to make trustworthy. Both numbers matter, so both are now reported and each is labelled: the pool queue target is what the queue was measured against, the loaded target is the in-flight buffer that raising the factor would grow. This also matches the sibling "stepped up loading factor" debug line. LoadFactorCeilingReportingTest now asserts on the values in both the debug and warn messages - not asserting on them is what let this through. Also makes lastWorkRequestWasFulfilled volatile. Adding the test-visible setter widened writes past the control thread that owns the field, and SpotBugs was right to flag it (AT_STALE_THREAD_WRITE_OF_PRIMITIVE, new vs base). The field is touched once per control loop pass, so the barrier is free; verified the finding is gone from spotbugsXml.xml locally. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
Review responseReplying at PR level because there are no inline review threads to reply into - the review landed as a 1. "the new messages report the wrong target number" - agreed, fixed in d2ec57fCorrect, and worth catching. One refinement on the suggested fix. Both numbers are worth having, so rather than dropping the loaded
You also correctly identified why it got through - neither test asserted on the values. Both now do, 2. SpotBugs
|
|
Claude finished @astubbs's task in 2m 39s —— View job Claude's review of the follow-up fix (commit d2ec57f)Todo list
SummaryBoth items from my previous review are correctly resolved in d2ec57f. 1. Wrong target number — fixed correctly. I ran the test to confirm, both by reading the new assertion and by executing it: 4/4 tests pass. Captured log output for the fixed-factor case confirms the numbers now line up:
2. SpotBugs Other checks:
No further issues found. This is ready from my side. |
Scope note for whoever picks this upThis PR deliberately does not close #155, and there is no closing link in the description. On merge, #155 stays open. Intentional. Done here: the log-noise half. The WARN no longer fires every control-loop pass - a fixed factor (set via Not done, deliberately: the underlying load-factor behaviour is unchanged. The argument in this PR is that you must not change buffering behaviour to silence a log line, so the dynamic-at-cap case keeps its signal rather than being demoted. If a user is genuinely pinned at Decision needed before #155 is closed by hand: whether #155 was ever about more than the noise. If it was only ever the log spam, re-scope and close it. If the saturation behaviour itself needs work, that is a separate issue and should be opened before #155 is closed, or it will be lost. Also note for a reviewer: the |
Brings in the repo-hygiene workflow whose two new required checks (shell: sigpipe, workflows: action versions) this branch predated, so the PR was blocked waiting on contexts it could never produce. Conflict: src/docs/development/upstream-map.yaml. #211 slimmed the schema (dropped `forwarded`, `todo`, `backlink`, the long-tail DEFERRED block and scripts/upstream-backlink.sh) and mirrored every open confluentinc issue into this fork. Resolved by taking master's file whole and re-adding the issue-402-max-load-factor-log-noise entry in the new shape: `forwarded`/`todo` dropped (no tooling reads them now), the backlink action folded into notes, `fork_issue: 155` recorded now that confluentinc#402's mirror exists, and every issue reference qualified by repo per the new house rule. scripts/upstream-map.py validate passes. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
#211 made a bare `#NN` below #1000 a CI failure on added lines: the fork's numbers sit entirely inside confluentinc's range, so an unqualified reference is a coin flip. Three added lines in docs/inflight/pr-155-load-factor-noise.md tripped the gate; the javadoc in AbstractParallelEoSStreamProcessor and LoadFactorCeilingReportingTest passed only via the "upstream confluentinc#402" escape hatch, which the same commit deprecates in favour of naming the owner. Both now say #155 / confluentinc#402. Also moves the "answer the original reporter when this merges" note out of upstream-map.yaml and into the inflight doc. AGENTS.md is explicit that the manifest has no todo: field and loose ends belong in docs/inflight/ - the field was already dropped when the manifest was slimmed, so leaving the note there would have been an entry no tooling reads. Verified with .github/scripts/issue-ref-gate.js over this branch's diff against master: clean. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
Merged master in; three things it changed hereMerged 1. One conflict, in The 2. The new issue-reference gate fires on this PR, so I fixed it. Three added lines in 3. This PR is the change that would have tripped the SIGPIPE bug. Recording it because it is the Nothing else from master required changes
LogCapture, re-checked as asked: still accurate. Neither this PR's inline Also added a recommended merge strategy to the PR body, per the rule c6fff83 just added: squash, |
… of the index Two things #211/#212 surfaced in this PR's own files. #212's lesson - await/assert the thing itself, never a proxy - has an adjacent shape here worth naming. fixedMessageBufferSizeDoesNotWarnOnEveryPass asserts NO warnings, which would pass vacuously if the appender were ever attached to the wrong logger. It is not vacuous today, because the debug assertion below it can only hold when the capture is live and pointed at the code under test - but nothing said so, and the two are separable by a well-meaning edit. Now they are commented as a pair, pointing at the write-up. The test needed no other change: it is fully synchronous, driving 500 checkPipelinePressure() passes on the test thread and reading the appender after, so there is no await to get wrong. Also rewords the upstream-map note that said "this manifest has no todo: field". bin/todo-index.sh read the literal marker and wanted to index it, which is the gate working - the fix is to stop writing a marker in prose, not to regenerate the index around a false entry. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
Follow-up: #212's lesson checked against this PR's tests, and one gate false-positive fixedTwo additions since the merge comment above, in f0e3a0e. #212 ("await the metric, not a counter that leads it") - checked, no overlap, but one adjacent
Gate status on the merged tree, all run locally: |
|
Claude finished @astubbs's task in 2m 57s —— View job Claude's review of PR #201 (re-review after synchronize)Todo list
SummaryBoth items from my previous two reviews (wrong-target-number fix,
Re-verified the core fix is intact post-merge. Verification run on the current tree (
No new issues found. This PR is ready from my side. |
…overlap Two things master now requires that this branch predates. Issue references: the new gate in .github/scripts/issue-ref-gate.js flags an unqualified #NN below #1000 on added lines, because the fork's numbers sit entirely inside confluentinc's range and a bare number resolves against whichever repo the reader is in. This branch added 21 such references. They are now astubbs#NN / confluentinc#NN per AGENTS.md, which also asks new writing to name the owner rather than say "upstream". upstream-map.yaml: AGENTS.md now states the manifest has no `todo:` field - loose ends belong in docs/inflight/. This entry carried the only `todo:` key in the file; dropped. Separately, the #201 overlap was overstated here and needed correcting on the facts rather than restating. #201 has no LogCapture class at all - it has the same logic inline and private to LoadFactorCeilingReportingTest. So there is no symmetric "whichever merges second deletes its copy": this branch adds the only such class, nothing here needs deleting in either merge order, and the single follow-up is converting that one inline block onto LogCapture. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RtNUsxokE9g2pSEjBHZqNA
1 participant
Description
Fixes the log-noise half of #155, the fork mirror of
confluentinc/parallel-consumer#402:
isPoolQueueLow(): Max loading factor steps reached: 100/100, repeated forever.The mechanism
AbstractParallelEoSStreamProcessor#checkPipelinePressure()runs on every control loop pass, andlogged that line at WARN, unrate-limited, whenever
DynamicLoadFactor#isMaxReached()held. Twoconfigurations reach that state, and both spam:
100/100. Once the queue has been below target longenough to step 2 -> 100, the condition is permanent, so the line repeats for the life of the process.
PCModule#initDynamicLoadFactor()buildsDynamicLoadFactor(n, n)whenmessageBufferSizeis set, soisMaxReached()is true from construction and the WARN fires from thefirst pass onwards. That is what the README's own PARTITION-ordering tuning advice tells people to
configure, so following it earns you permanent log noise saying nothing is wrong.
Measured by the new test: 500 control loop passes produced 500 warnings, in both configurations.
The fix (reporting only - buffering behaviour is untouched)
DynamicLoadFactor#isStaticFactor()- true when the factor starts at its own ceiling(
messageBufferSize, orinitialLoadFactor == maximumLoadFactor). Such a factor never steps, somaybeStepUp()now short-circuits instead of engaging the cool-down/warm-up machinery, and theceiling is reported at debug: the user asked for a fixed buffer, and getting one is not a warning.
PCModulestates the intent through a newDynamicLoadFactor.fixedAt(n)factory.which a user may want to act on - but rate limited to once per 30s via the existing
RateLimiter(as already used by
BrokerPollSystemandProcessingShard), and reworded so it reads as saturationand names what to change, rather than reading like a failure. Deliberately not demoted to debug:
weakening a real signal is the wrong way to fix a volume problem.
measured against (
getPoolLoadTarget(), whatisPoolQueueLow()compared), and the loaded in-flighttarget (
target x factor) that raising the factor would grow. An earlier revision printed only thelatter under the "queued vs" phrasing, which reported
0 queued vs 1008for a check that had tested0 vs 16- caught in review, and now asserted on by the tests.To answer the original reporter's question directly: the message means PC has scaled its in-flight
target to the configured ceiling and will not ask for more. It is a saturation signal, not an error, and
on its own it does not explain a stall. The stall in that report was a separate defect, fixed in
confluentinc#547 / confluentinc#606 and further in the
confluentinc#857 family here (#119) - nothing in this PR touches it.
Tests
LoadFactorCeilingReportingTest(core, surefire, no broker) drives the realcheckPipelinePressure()pass 500 times throughTestParallelEoSStreamProcessorand asserts oncaptured log output:
fixedMessageBufferSizeDoesNotWarnOnEveryPass- withmessageBufferSizeset: the factor is confirmedstatic and maxed from construction (the diagnosed mechanism), and zero WARN/ERROR is emitted, with the
condition still observable at debug. Reverting the fix turns this red with 500 warnings.
dynamicFactorAtCeilingWarnsOnceNotEveryPass- a dynamic factor sitting at its cap warns exactlyonce, with the reworded text. Reverting the fix turns this red: 500 instead of 1.
compared against and the loaded target it named - which is the check that was missing when the
wrong-target defect got in.
fixedFactorNeverSteps/factorWithHeadroomIsNotStatic- theisStaticFactorcontract itself.The load factor is wired through
PCModulein both cases, not poked in afterwards. The class is@Isolated+SAME_THREADbecause it captures a class-wide logger (a first cut caught a siblingtest's output).
This PR is what would have tripped the SIGPIPE bug #211 fixed
Worth recording, since it is the concrete case the fix was reasoning about.
bin/check-quarantine-owners.shpiped a whole source file into
grep -qunderpipefail, which reports failure exactly when itmatches once the file exceeds the 64 KiB pipe buffer.
AbstractParallelEoSStreamProcessor.javasat at65,185 bytes - 351 under the 65,536 limit. This PR takes it to 68,761 bytes, i.e. 3,225 bytes
over.
Reproduced on the merged tree: the old
git show | grep -qform reports failure on 9 of 20 runsagainst this branch's version of the file, and never against master's. The herestring form on master is
correct every time. Nothing to change here - the bug is already fixed, and
bin/check-shell-sigpipe.shnow guards the class repo-wide - but this branch is why the headroom mattered.
Note for whoever merges this: log-capture helper collision
This PR does not add a shared log-capture utility. Its capture is a handful of lines of
ListAppenderprivate toLoadFactorCeilingReportingTest. Sibling PR #203(
fix/log-verbosity-batch) adds a reusableio.confluent.csid.utils.LogCapturefor the same job.Neither is on
master, so they cannot be unified before one of them lands. Whichever of the twomerges second should delete its own copy and use the other's - recorded in
docs/inflight/pr-blockers-and-collisions.md. If a duplication or similarity report flags the two, thatis the reason, and this is the agreed resolution.
Recommended merge strategy: squash
Per AGENTS.md -> PR Discipline. The branch is one idea - stop the ceiling report spamming the log - plus
a review fix-up, a manifest bookkeeping commit, a master merge and a convention sweep. None of those are
workstreams anyone would bisect to or revert independently, so re-cutting buys nothing and rebasing
as-is would put four commits on master where one belongs. Suggested squash message:
Checklist
docs/inflight/pr-155-load-factor-noise.md(mechanism, why the dynamic WARNstays a WARN, the reported-numbers correction, and the loose end for merge time), the
issue-402-max-load-factor-log-noiseentry inupstream-map.yaml, and adocs/refactoring.mdnoteon the untestable hard-coded step timings. No user-facing doc change: behaviour is unchanged.
CHANGELOG.adocdeliberately untouched per AGENTS.md.LoadFactorCeilingReportingTest, verified red before the fix.