PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach - #44
Draft
WillemHoman wants to merge 6 commits into
Draft
PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach#44WillemHoman wants to merge 6 commits into
WillemHoman wants to merge 6 commits into
Conversation
added 6 commits
August 6, 2026 19:53
… overhead across Resque forks
…lush that waits on the drain thread
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.
Jira: PAYMENTS-11727
Not for merge. Companion to #43. Together they show the
specs added in #45 catch both prior regressions, one each.
What? Why?
The PAYMENTS-11567 attempt at in-child metric collection shipped in
bigpay#10597 and was reverted for raising Resque job time from 20ms
to 500ms. That code lived in bigpay, not here, so it cannot be cherry-picked.
849252breconstructs its one load-bearingline instead: the child delivers by calling
client.stop(wait_timeout_seconds: 2), which waits on the background drainthread rather than sending on the calling thread.
Everything else is #43's branch unchanged, so the specs are byte-identical between the two PRs.
The result is the mirror image of #43. Completeness passes, overhead fails. That is the PAYMENTS-11567 signature:
the observations did arrive, they were just unaffordable.
Reproducing the 480ms
56ms fails the budget but is an order of magnitude short of the figure recorded in production, so it is worth explaining
rather than leaving as an inconsistency. What the measurements show is a cliff, not a gradient.
Two mechanisms are in play and only one of them involves a sleep.
stoppollswhile @queue.length > 0in 50ms steps.The queue is emptied by a background thread whose loop is
drain, then sleep client_thread_sleep, 0.5 seconds. So:stopreturns having lost one 50ms poll.stopcannot return until the thread wakes. The child is pinned tothe end of the sleep window.
Measured per job over 100 jobs, varying how many pushes the job makes and how much work separates them:
Read the total column. It is constant at 527 to 566ms across every row in the second regime, whatever the job did in
between, and the 40ms spread is the 50ms poll granularity. The delta column declines only because it subtracts a control
run that performed the same gap, which hides whatever part of the wait overlapped the job's own work.
So the predicate is not how many metrics a job pushes, and not how long the job takes. It is whether any push lands after
the thread's first drain. Two pushes back to back cost 63ms; the same two pushes 50ms apart cost 527ms.
That is exactly the reported 20ms to 500ms. The bigpay job recorded queue latency on entry and publish duration after the
RabbitMQ round trip, so its second push always landed mid-sleep and it hit the ceiling on every job. A job pushing once
at the end would have paid 55ms and might never have been noticed.
The overhead example on this branch reports the 55ms row, because the probe job pushes once and returns. To see the
ceiling, apply this to the probe job. It is deliberately not committed, so that the specs stay identical to #45 and
#43:
What this says about the fix
The shipped
flush!drains on the calling thread, so neither mechanism applies: there is no cadence to wait on and nopoll to lose. 0.83ms against 527ms for the same feature. The difference between affordable and not was never in-child
collection itself, only which drain primitive the child called.
How was it tested?
ruby-3_4-rspec_fork_integrationis expected to be red on this branch, on the overhead example only.