Skip to content

fix(platform): PAYMENTS-11727 Deliver metrics pushed from inside a Resque job - #42

Closed
WillemHoman wants to merge 11 commits into
mainfrom
PAYMENTS-11727-resque_latency_metrics_clear_queuq
Closed

fix(platform): PAYMENTS-11727 Deliver metrics pushed from inside a Resque job#42
WillemHoman wants to merge 11 commits into
mainfrom
PAYMENTS-11727-resque_latency_metrics_clear_queuq

Conversation

@WillemHoman

@WillemHoman WillemHoman commented Aug 6, 2026

Copy link
Copy Markdown
Contributor

Jira: PAYMENTS-11727

What? Why?

Metrics pushed from inside a Resque job were being dropped. Bigpay released 0.8.3 with
PROMETHEUS_RESQUE_PER_JOB_METRICS_ENABLED=1 and ruby_webhooks_published_counter fell to about 8% of normal on every
worker pod, recovering exactly on rollback. No webhooks were lost, no jobs failed and the queue never backed up. Only
the recording broke.

Two independent causes, both in how the client survives Resque's fork.

The child inherited the parent's outbound queue. The client is a singleton and its queue is ordinary process
memory, so fork copies it. JobMetrics.record_queue_latency enqueues in the parent on the line immediately before
super, which is the fork, so every child inherited that message and had to re-send it, and anything else pending,
before reaching its own. Fixed with a Resque.after_fork hook that gives the child a clean client. Nothing is lost:
the parent still holds the originals and sends them on its own schedule.

Pushing only queues, and exit! does not wait. Delivery happens on a background thread that wakes every
client_thread_sleep seconds. A Resque child ends with exit!, which runs no at_exit handlers and kills threads
outright, so an observation pushed near the end of a job was destroyed with the child. This predates 0.8.3 and was
costing observations quietly. Fixed by draining on the calling thread before the job returns, via a prepend on
Resque::Worker#perform, which is the in-child boundary. Measured cost is 0.90ms per job that pushes something and
nothing at all for jobs that do not. Disable with PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=0.

The two are complementary and ordered. Without the reset, the flush would synchronously send the parent's whole
backlog, which is the 480ms per job regression that got bigcommerce/bigpay#10597 reverted.

An empty queue is not an empty wire. Found by the bench below, on its first run. The flush originally returned early
when nothing was queued, and the queue reads as empty the instant the background thread pops the last message, well
before that message reaches the collector. exit! then destroyed the request. Roughly 0.1% to 0.3% of in-child pushes,
silently, because the process that would have logged it was already gone. Confirmed at the socket layer: the listener
accepted every connection but read fewer complete requests, and the shortfall matched its count of connections opened
and then closed with no request line. Fixed by serialising both drain paths on a delivery mutex, so a flush cannot
return while a send is in flight. That also closes a hang where both threads saw one queued message, both called pop,
and the loser blocked forever.

A job should not wait long on the metrics pipeline. Making the child wait for delivery means it now waits for a
collector that is not answering, and 0.8.3 has no such exposure because nothing in a job's code path ever touched the
network. Delivery is therefore bounded by PROMETHEUS_CLIENT_FLUSH_TIMEOUT, 20ms by default, covering the wait for the
lock as well as the requests. Past it the observations are abandoned, because availability of the work beats
completeness of its metrics.

Also in here:

  • Bounded connect, response and write timeouts when delivering. Net::HTTP defaults all three to 60 seconds, which
    is survivable on a background thread and not survivable inline in a job.
  • A warning when observations are abandoned, flushed out of the process before exit! destroys it. exit! runs no
    handlers and empties no buffers, so a line written to a buffered STDOUT in a child never reaches the log. This
    applied to the warnings the client already emitted, which have been unreliable in children all along.
  • bin/resque_fork_bench, a manual tool that forks real children and reports both what arrived and what it cost, with
    a --smoke-test sweep. Every number below came from it.
  • resque and sinatra >= 4.0 as dev dependencies. Resque pulls sinatra with a loose constraint and, with no
    Gemfile.lock in this repo, a cold CI resolve was free to pick a sinatra that caps rack < 3 against the gemspec's
    rack >= 3.0. This is the dependency work deferred from PAYMENTS-11727 Resque latency metrics #31.
  • A boot log stating whether the child flush is installed, so the kill switch can be confirmed during an incident
    rather than inferred.
  • Release 0.8.4.

How was it tested?

spec/bigcommerce/prometheus/client_spec.rb — unit coverage for #flush! and #reset_after_fork!: delivery on the
calling thread, never raising into the caller, waiting for an in-flight send, giving up on the deadline, bounded
timeouts on both paths, and clearing of the queue, worker thread, both mutexes and socket state. One example binds a
real socket that accepts and never answers, because a timeout cannot be asserted against a stub.

spec/integration/resque_fork_delivery_spec.rb — black box, forking real Resque children against a real listener.
Asserts two properties and deliberately mentions neither queues nor forks, because past changes have broken each from
opposite directions:

  • Completeness. 100 jobs run, 100 observations arrive.
  • Overhead. Per-job cost stays under budget, measured against an identical run with metrics disabled so machine speed
    cancels out.

Excluded from the default run and given its own job, ruby-3_4-rspec_fork_integration. The ruby executor already
provides redis, so no service needed adding.

None of it is vacuous, and each was checked by removing the fix:

property without the fix
completeness 0 of 100 with PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=0
waits for an in-flight send fails, the flusher thread is already dead
gives up on the deadline takes 5.01s against a stalled collector, fails < 1.0

Cost of serialising delivery, A/B on the same machine, medians of five runs at one push and three at five:

metrics pushed per job before after
1 1.4 ms 1.9 ms
5 3.2 ms 4.7 ms

Roughly half a millisecond on the shape bigpay runs. That is the calling thread paying for a request it previously
handed to a thread that was about to be killed.

Cost when the collector is not healthy, 50 jobs pushing one metric each:

collector per job delivered
healthy 6.1 ms 50/50
dead, connection refused 5.1 ms 0/50
saturated, 20ms bound 27.8 ms 0/50
saturated, 1s bound 1011.8 ms 0/15

The last row is what the per-request timeouts alone would give. A dead collector costs nothing, since ECONNREFUSED is
immediate. Only a saturated one is expensive, and that is what the bound exists for.

Two draft PRs run these same specs against the two regressions they exist to catch, one property failing on each:
#43 on 0.8.3 as released, where completeness fails at 0 of 100, and #44 on the PAYMENTS-11567 approach, where
completeness passes and overhead fails. Both are expected to be red and are not for merge.

A connection-reuse optimisation was also written and measured, then dropped: the difference was inside run-to-run noise
and did not justify the complexity.

@WillemHoman

Copy link
Copy Markdown
Contributor Author

Superseded by #45, which carries the same work on the correctly spelled branch with the history rebuilt into nine reviewable commits.

The proof PRs #43 and #44 have been repointed at #45. Closing as won't-merge; the branch is left in place for now.

@WillemHoman WillemHoman closed this Aug 8, 2026
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