Skip to content

PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach - #44

Draft
WillemHoman wants to merge 6 commits into
mainfrom
PAYMENTS-11727-proof-11567-flush-latency
Draft

PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach#44
WillemHoman wants to merge 6 commits into
mainfrom
PAYMENTS-11727-proof-11567-flush-latency

Conversation

@WillemHoman

@WillemHoman WillemHoman commented Aug 6, 2026

Copy link
Copy Markdown
Contributor

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. 849252b reconstructs its one load-bearing
line instead: the child delivers by calling client.stop(wait_timeout_seconds: 2), which waits on the background drain
thread 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.

1) metric delivery from Resque forked children overhead adds less than the per-job budget over an identical run with metrics disabled
   Failure/Error: expect(measured_overhead_per_job).to be < OVERHEAD_BUDGET_SECONDS

     expected: < 0.025
          got:   0.05581208999967203

2 examples, 1 failure

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. stop polls while @queue.length > 0 in 50ms steps.
The queue is emptied by a background thread whose loop is drain, then sleep client_thread_sleep, 0.5 seconds. So:

  • If the queue is already empty by the time that thread first sleeps, stop returns having lost one 50ms poll.
  • If anything is queued after that first drain, stop cannot return until the thread wakes. The child is pinned to
    the end of the sleep window.

Measured per job over 100 jobs, varying how many pushes the job makes and how much work separates them:

pushes gap between them control total job time delta against control
1 n/a 6.1 ms 61 ms 55 ms
2 none 4.0 ms 63 ms 59 ms
2 0.05s 60.4 ms 527 ms 466 ms
2 0.20s 213.2 ms 536 ms 322 ms
2 0.30s 312.4 ms 559 ms 246 ms
2 0.45s 463.6 ms 566 ms 103 ms
3 0.05s 114.1 ms 543 ms 429 ms

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:

   def self.perform(_payload)
-    Bigcommerce::Prometheus.client.send_json(
-      type: 'fork_delivery_probe',
-      name: METRIC_NAME,
-      value: 1.0
-    )
+    2.times do |index|
+      sleep(0.05) if index.positive?
+      Bigcommerce::Prometheus.client.send_json(
+        type: 'fork_delivery_probe',
+        name: METRIC_NAME,
+        value: 1.0
+      )
+    end
   end

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 no
poll 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?

redis-server --port 6399 --save '' --appendonly no --daemonize yes
FORK_INTEGRATION=1 REDIS_URL=redis://127.0.0.1:6399/15 bundle exec rspec spec/integration

ruby-3_4-rspec_fork_integration is expected to be red on this branch, on the overhead example only.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant