PAYMENTS-11727 Deliver metrics recorded inside Resque jobs by WillemHoman · Pull Request #45 · bigcommerce/bc-prometheus-ruby

WillemHoman · 2026-08-07T05:45:59Z

What? Why?

Re-release of #31

When released to BigPay, ruby_webhooks_published_counter fell to about 8% of normal on every resque worker pod.
This manifested as an alert for Webhooks not being delivered in BigPay

No webhooks were lost, no jobs failed and the queue never backed up. Only the recording broke.

The problem: each forked child inherits the parent's metrics queue

The update made in v0.8.3 #31 introduced metrics for job queue latency which are captured in the parent resque process which forks the child workers.

The Prometheus client library is a singleton and its queue is ordinary process memory, so fork copies it.

This means each worker process, inherited the metrics which the parent queue had not yet sent.
This resulted in each child having to resend these metrics prior to sending it's own.

Nothing in bc-prometheus-ruby flushed the metric queue prior to exit.
Metrics being sent, relied on the worker thread pushing the metrics to the collection endpoint quicker than the job took to run.
As a result of the increased quantity of metrics in the queue, the worker process exited prior to the queue being flushed.
This meant the workers own metrics did not get reported triggering the alert as it moved the reporting threshold from about 2ms to 25-50ms which is longer than it took for the job to complete.

The fix in two parts

Clear the queue on fork

A Resque.after_fork hook now hands each child a clean Prometheus client with an empty queue.
Nothing is lost: the parent still holds the original metrics and it's own metric worker thread will flush them.
This reverts the behaviour to the pre 0.8.3 release.

The opt-in part: flush the metrics queue prior to exit

This fixes the long-standing race condition which relied on the metrics being flushed more quickly than it took for the job to run.

If a prometheus metric was recorded immediately prior to the job ending, it would 100% of the time as the child would exit prior to the metric being flushed.

To address this, a prepend on Resque::Worker#perform, the in-child boundary, drains the job thread before the job returns.

Note that this is an immediate flush bounded by a 20ms budget instead of waiting on the thread's sleep loop which was the approach originally taken in https://github.com/bigcommerce/bigpay/pull/10597.

Prometheus metrics delivery happens on a background thread that wakes every client_thread_sleep seconds which is 500ms.

https://github.com/bigcommerce/bigpay/pull/10597 waited on the metrics reporting thread to wake up and flush the queue which meant that it could wait up to 500ms before doing so.

The flush timeout is configurable by , which is defaulted to 20ms.

As this does add latency of PROMETHEUS_CLIENT_FLUSH_TIMEOUT ms to every job, the introduced flush on exit is off by default.
Enable with PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED=1, or by assigning resque_child_flush_enabled.

resque_child_flush_enabled also accepts a callable, asked in the parent before every fork. The child
inherits this setting through the fork.
For example in the app such as BigPay which relies on bc-prometheus-ruby, you can control this via a LaunchDarkly experiment.
This allows the flush on exit behaviour to be disabled without having to update the PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED env var and restarting the pods.

config.resque_child_flush_enabled = lambda do |job|
  MyFeatureFlags.enabled?('resque_child_metric_flush', queue: job.queue)
end

How was it tested?

The spec/integration/resque_fork_delivery_spec.rb integration test was added.
This is black box test, forking real Resque children against a real listener.
It asserts two properties

Completeness. 100 jobs run, 100 observations arrive.
Latency. Per-job cost runs within a given time.

This test was deployed against two test branches at v0.8.3 to confirm that it would have caught the issues in the last release due to having to flush the parent's metrics as well as the workers:

PAYMENTS-11727 Proof: the fork delivery specs fail on 0.8.3 as released #43: non-delivery of metrics which triggered the alert above
PAYMENTS-11727 Proof: the fork delivery specs fail on the PAYMENTS-11567 flush approach #44: increase in latency due to having to flush the parent's metrics as well is it's own.

Note

Medium Risk
Always-on fork reset changes every Resque fork-per-job worker’s metrics path; opt-in flush adds bounded job latency and can drop metrics on timeout, though defaults preserve prior flush-off behavior aside from the reset fix.

Overview
Release 0.9.1 fixes Resque forked workers dropping or distorting Prometheus metrics after parent-side queuing grew in 0.8.3.

Always on: prepending ForkReset on Resque::Worker#perform calls Client#reset_after_fork! in forked children (PID change only), clearing the inherited outbound queue and rebuilding delivery state so children no longer replay the parent backlog or double-count. Reset runs before after_fork hooks.

Refactor: HTTP posting moves from Client to new Delivery, with flush! (returns :empty, :success, :timeout, :error), mutex-serialized sends, and a wall-clock cap via PROMETHEUS_CLIENT_FLUSH_TIMEOUT (default 20ms). Abandoned metrics log with STDOUT/STDERR flush for Resque children.

Opt in: PROMETHEUS_RESQUE_FLUSH_ON_EXIT_ENABLED / resque_flush_on_exit_enabled prepends FlushOnExit to synchronously drain the job’s queue before the child exits when fork_per_job?. README and config document behavior; overriding Client#uri_path no longer changes where metrics are posted.

Testing/CI: Resque + Sinatra in the Gemfile, unit specs for client/delivery/Resque hooks, opt-in spec/integration fork tests (FORK_INTEGRATION=1, Redis), and a Ruby 3.4 CircleCI job for those specs.

^{Reviewed by Cursor Bugbot for commit 4e1625a. Bugbot is set up for automated code reviews on this repo. Configure here.}

cursor

Cursor Bugbot has reviewed your changes and found 1 potential issue.

^{❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.}

^{Reviewed by Cursor Bugbot for commit 8740ec7. Configure here.}

Catsuko · 2026-08-25T05:58:00Z

+        http.open_timeout = timeout || @open_timeout
+        http.read_timeout = timeout || @read_timeout
+        http.write_timeout = timeout || @write_timeout


💭
Likely doesn't matter but these timeouts don't keep a request's total duration under the timeout duration so a flush can potentially exceed the flush timeout given slow phases of the request.

Good catch, I have refactored this to use a timeout on a background thread

Catsuko · 2026-08-25T06:19:27Z

+          def perform(job, &block)
+            super
+          ensure
+            ChildFlush.flush if fork_per_job? && ChildFlush.enabled


💭

No required change but it is interesting you can turn forking off. I also saw there are gems that tweak how forking works where one fork handles a variety of jobs: https://github.com/stulentsev/resque-multi-job-forks

Maybe there is an alternative to enabling these metrics where we don't need to struggle with the forking so much. I don't know enough about Resque to have a good judgement on it but I wanted to leave a comment to see if anyone else has thoughts on this 🧑‍🎓

Catsuko · 2026-08-25T06:22:12Z

💭 If it is helpful to anyone, I was comparing the implementation here to some other libraries I know that have resque integrations and have to solve the same problem of getting stuff out of the forked thread:

I found it useful to do so in order to think about trade offs and potential pitfalls

bc-chenli

Looks good to me overall (good to learn how the Resque fork process works), have some random questions.

I will go through the changes on lib/bigcommerce/prometheus/client.rb as a separate review session. (Since this is a not big but heavy PR to review).

Good fix 👍

bc-chenli · 2026-08-27T00:23:09Z

+### Turning it on and off at runtime
+
+`resque_child_flush_enabled` also accepts anything callable, which is asked in the **parent** before every fork. The
+child inherits the answer through the fork, so a feature flag client never has to survive one:
+
+```ruby
+Bigcommerce::Prometheus.configure do |config|
+  config.resque_child_flush_enabled = -> { MyFeatureFlags.enabled?('resque_child_metric_flush') }
+end


Like the Turning it on and off at runtime example 👍

…esque children

…before it exits

…its for an in-flight send

…t abandons

…e in the parent before each fork

… overhead across Resque forks

…led flush `drain` reports the one message it was carrying when a send fails, then re-raises. Everything queued behind that message is left untouched. `report_outcome` excluded the `:error` outcome entirely, so those were destroyed by the forked child's `exit!` with no warning at all. A job that queued five observations and failed on the first only ever heard about one of them. `:error` now reports whatever is still queued, the same as `:timeout`. It still does not claim anything was in flight, since on an error path nothing was.

…to its own class The bounded child flush left `Client` doing two jobs. It was the exporter-client subclass, and it was also the whole delivery path: the lock, the deadline, the per-message requests and the reporting. `drain` and `post_message` are not overrides of anything upstream, and they are not flush-specific either. They are the one path both the background thread and the child's flush take, separated only by whether a deadline is passed. `Delivery` now owns that path, so the two callers cannot drift apart. `Client` keeps what the superclass needs, and hands its queue to a `Delivery` it rebuilds whenever that queue is replaced. A fork therefore gets a fresh queue and a fresh delivery lock together, which is what it needed anyway. No behavior change. The `Metrics/ClassLength` override goes with it. Its comment argued that splitting the class would mean handing a collaborator most of the client's state. Both classes now fit under the default.

…after_fork! The three socket ivars this cleared were always nil. `ensure_socket!` is the only method that assigns `@socket`. Upstream's `process_queue` is its only caller. This gem has overridden `process_queue` without calling `super` since v0.1.0, where the CHANGELOG records the move from direct sockets to Net::HTTP. Even if that path came back, the resets would still be redundant. Upstream's `ensure_socket!` opens by comparing `@socket_pid` to `Process.pid` and clearing all three itself, so it already self-heals across a fork. The accompanying spec set the ivars by hand to a state the code cannot reach, then asserted they were cleared. That tested the assignments rather than any behavior.

…et::HTTP defaults The flush sets its own per-message timeout from its budget. It never read the three configured values. Only the background thread did, and nothing waits on that thread. Keeping them meant every upgrading user had background delivery re-timed from 60 seconds to roughly one. That included everyone who never enables the child flush. Removing them restores parity with main on the path nobody opted into changing. Drops `PROMETHEUS_CLIENT_OPEN_TIMEOUT`, `PROMETHEUS_CLIENT_READ_TIMEOUT` and `PROMETHEUS_CLIENT_WRITE_TIMEOUT`, which have not shipped in a release.

…ith a watchdog Net::HTTP caps connect, write and read separately. It does not bound a request as a whole. A flush configured for 20ms could therefore take 60ms. The flush now runs on a thread that is stopped once the budget is spent, so the setting means what a reader would expect it to mean. `Thread#kill` runs ensure blocks, so the delivery lock is released rather than left held by a dead thread. Per-phase caps go back to the whole remaining budget. Dividing them three ways also held the bound, but it quietly enforced a third of the configured value. A stalled collector cost 10ms against a 20ms setting, with the budget still holding room. Measured against a stalled collector, a job now waits 22.9ms on a 20ms budget. The remainder is the abandonment report and the thread itself.

…l it has run in production The timeout defaults have no production track record, and comment 5 already moved one of them once. A reader enabling this deserves to know the numbers may still change, and where to look when they do. Scoped to the opt-in flush rather than the whole section. The fork-time queue reset above it is always on and is not experimental.

…e accessor rather than after `self.enabled = false` trailed the `class << self` block it belongs with, several lines below the `attr_accessor` it initialises. The default now sits at the top of the module body as a plain ivar, which is the same one the accessor reads. Assigning through the writer does not work in either position. The accessor does not exist yet at that point in the body. Inside `class << self` the receiver is the singleton class, which does not have the writer.

…ate methods once Four `private_class_method` calls, one after each definition, become a single `private` marker inside a `class << self` block. No behavior change. Verified that `start` stays public and that the other four stay private on the singleton.

…ch path reported it The watchdog added in 10ba436 races `drain`'s own deadline. The watchdog's join starts marginally earlier, so either can win. Both report the loss. `drain` names the message it was carrying, and the watchdog reports an in-flight send instead. The example asserted only the first wording, so it failed roughly half the time. It now accepts either, which is the contract: a stalled collector is never silent.

`ChildFlush` said nothing about when it runs, which was the review comment. It was ambiguous in a second way too. The client keeps a background thread that also delivers metrics. So "child" read as easily as the child thread as the forked process. "Fork" can only mean a process, so that reading goes away. The name now pairs with the sibling `ForkReset`, and the two bracket a forked child's life at both ends. Reset when the fork begins, flush before it exits. The config surface is renamed with it, so the class and the setting stay in step: PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED -> PROMETHEUS_RESQUE_FORK_EXIT_FLUSH_ENABLED resque_child_flush_enabled -> resque_fork_exit_flush_enabled None of these have shipped. Every one is introduced by this branch, so the squashed diff shows only the final name.

…cs are always lost The message said metrics recorded inside a job "are not delivered" when the flush is off. That is false for any job that does work after pushing. The child starts a delivery thread on the first push, and upstream runs its loop once before sleeping. So delivery is a race against `exit!` rather than an impossibility. Measured 0 of 100 arriving when a job pushes and returns, and 100 of 200 when it pushes, works for 50ms, then pushes again. What the flush adds is reliability, not delivery, and the message now says so. The surrounding prose already hedged this correctly. The README and the module doc both say a child is "normally" torn down first, so only the log overstated it. Adds the first coverage of that boot-time signal, including an example that fails against the old wording.

…ort the fork exit flush `Integrations::Resque.start` accepts any client, so a plain `PrometheusExporter::Client` can reach the install. It has no `flush!`. `ForkExitFlush.flush` already guards for that, but stays silent on purpose. It runs inside an `ensure` where raising would replace whatever the job was raising. So a caller who enabled the flush and passed an unsupported client got no signal at all, at boot or per job. Boot is the one place a complaint is safe. It is the long-lived parent, once, well away from any job's exception handling. Nothing is prepended, and the install stays unmarked so a later call with a usable client still works. The two logging branches move into their own methods to keep the install readable.

…specs cannot run Two ways this suite reported green while forking nothing. A missing redis was skipped. The tag filter means that hook only runs when someone asked for these specs, so the skip could never spare a developer who had no redis. It only ever turned an explicit request into a pass. It now raises. A filter matching no examples also passed. Pointing rspec at spec/integration without FORK_INTEGRATION set reported "0 examples" and exited 0, so dropping the env var from CI would have looked like a green run. `fail_if_no_examples` closes that, and covers any future tag wired the same way. Both cases exited 0 before this and exit 1 after. Verified by stopping redis and by running the directory without the env var.

…ration job The comment called this job opt-in. The job is not conditional. The suite is, and this job opts in on its behalf by setting FORK_INTEGRATION. It also said nothing about how the separation is enforced. That matters, because the gate is the :fork_integration tag rather than the directory. `additional_args` alone would run nothing, so anyone who removed the hook below would stop the specs running rather than narrow them. Records that both of those now fail rather than pass quietly. Also drops the note about one ruby version being enough.

…and when Two claims here were wrong in the same way the boot log was. "anything a job pushes is normally destroyed with the child" overstates it. What is lost is whatever is still queued when the child exits. The hedge was on the wrong noun: undelivered pushes are always lost, not usually. "a background thread that wakes every client_thread_sleep seconds" is wrong too, and it is what made the first claim look reasonable. Upstream runs `worker_loop` before its first sleep, so the first push triggers an attempt straight away rather than half a second later. That model predicted 0 of 200 delivered for a job that pushes, works 50ms, then pushes again. The measured figure is 100 of 200. The docs now match.

Catsuko

Seems reasonable to me. Hard for me to judge if the timeouts are too strict or not however I'm not concerned since we can opt-in to changes via a lower priority worker and test without needing to affect our higher value jobs.

bc-chenli

Looks good 💯

…ration job The comment said the specs were excluded unless FORK_INTEGRATION was set. It did not say where that exclusion comes from, or what sets the variable. A reader could not tell which part of the job was load bearing. It now names the three pieces in the order they fire. The :fork_integration tag sits on the spec's describe. spec/spec_helper.rb filters that tag out. The hook here sets the variable. The additional_args line now says what that setting does rather than what it does not.

…t it must re-send The ForkReset doc said everything the parent had not yet sent "has to be re-sent by the child". That reads as an obligation the child is meeting. It is the opposite. The child inherited a copy of a queue it has no business sending. The rule is now stated directly. Those messages are the parent's to send, and the child starts empty. The latency arithmetic that followed is gone, since the rule does not depend on it.

…t and name the install rule ForkExitFlush is three nouns and the first one is ambiguous. Resque forks a child per job, and the client delivers on a background thread, so "fork" left a reader guessing which of the two was meant. FlushOnExit says what happens instead of which mechanism it attaches to. The name invites one wrong reading, so the module doc now closes it up front. This is not an at_exit hook. Resque ends each child with `exit!`, which runs none, so the module wraps `Resque::Worker#perform` and flushes from its `ensure`. Renamed with it: the setting, the env var, the installer, the installed flag, and the three log helpers. `resolve_fork_exit_flush` becomes `should_flush_on_exit?`, which says a boolean comes back. ForkReset keeps its name, where "fork" is the actual trigger and is detected by pid. Also extracts the install guard. It read `unless resque_fork_exit_flush_enabled`, a bare truth test that hides a case: every callable is truthy, so a callable always installs. That is intended, since deciding per job needs something in place to ask, but nothing said so. The rule is now `flush_on_exit_possible?`, which tests for a callable explicitly and explains why. Behavior is unchanged throughout. The env var is unreleased, so renaming it costs nothing.

"anything a job pushes is normally destroyed with the child" overstates it. What is lost is whatever is still queued when the child exits. The hedge was on the wrong noun: undelivered pushes are always lost, not usually. "a background thread that wakes every client_thread_sleep seconds" is wrong too, and it is what made the first claim look reasonable. Upstream runs `worker_loop` before its first sleep, so the first push triggers an attempt straight away rather than half a second later. That model predicted 0 of 200 delivered for a job that pushes, works 50ms, then pushes again. The measured figure is 100 of 200. The docs now match.

…g callable option

…ush on exit

…_path delegator onto this branch Both were written while splitting this work into two pull requests and belong here too, so this branch stays a superset of the two. Client#uri_path was public before the delivery extraction and is restored as a one-line delegator. Client is a gem's public class, so removing the method outright would break any caller for no gain. Delivery#uri_path moves above the private keyword to back it. spec/integration/resque_fork_reset_spec.rb proves the reset end to end without involving the flush. It seeds the parent's queue immediately before each fork and asserts that nothing seeded reaches the collector. A second example drains the parent's queue afterwards, so a run where the seeding silently did nothing cannot pass for the wrong reason. A third clears ForkReset.installed_in_pid, which makes reset_if_forked return early and reproduces the behavior this work fixes: 210 of the parent's messages arrive across 20 jobs, every child re-sending the whole backlog it inherited.

@delivery

… the next one's metrics reset_after_fork! drops the reference to the delivery thread rather than stopping it. That is right in a forked child, where the thread did not survive the fork and there is nothing to stop. Calling it in a live process leaves the old thread running, and its loop reads @delivery fresh on every pass, so an orphan keeps draining whatever queue the client holds now. Two examples in the delivery spec therefore left two orphans behind, each waking every 0.5 seconds. The reset spec runs after them and needs a parent that stays silent while it seeds a backlog. It was instead seeing two or three of its seeds delivered by threads it did not know about, and failing about half the time. Both specs now stop the thread before resetting. Also renames the reset spec's JOB_COUNT, since a constant declared in a describe block lands on Object and collided with the delivery spec's.

…on job without naming the tag The tag name and the spec_helper filter are the parts most likely to be renamed. What a reader needs is that the specs are off in every other job, that the pre-exec hook is the switch, and that the directory argument is not. docs(platform): PAYMENTS-11727 Align the reset comments with the pull request that ships them This branch and PAYMENTS-12213-reset_queue_on_fork had drifted on wording for the same reset code, because the second was written by hand rather than carried across as a commit. Brings the reset-owned text into line, so the only remaining differences between the two are the flush. Left alone deliberately, because they describe code this branch has and the reset pull request does not: - reset_after_fork! keeps the numbered reason about the delivery lock, which only exists once the flush ships. - The client_spec example about the child inheriting a locked delivery mutex keeps its comment for the same reason. README keeps its own opening, which introduces queueing and exit! because it has to set up both features. The reset paragraphs now say that the parent sends the same messages too, so the observations are counted twice, which was missing, and gain the paragraph on the pid guard.

…hing lands Three comments used the same metaphor for three different things: a fork racing the mutex, a constant being defined on Object, and the reset running before the after_fork hooks. Each now names the mechanism.

… than on every job A client without reset_after_fork! was still prepended onto Resque::Worker. It then no-opped once per job, with nothing logged, so the ancestor chain advertised a reset that could never run. Capability is fixed when the client is passed in, so install_fork_reset settles it once, warns, and leaves the worker unwrapped. FlushOnExitInstaller already uses that shape for flush!.

… longer redirects delivery On main, Client#process_queue called uri_path on self, so an override or a stub changed where metrics went. Delivery builds its own URL now. The delegator still answers with the right value, but the comment describing it as kept for any caller invited the wrong conclusion. Also adds the delivery extraction to the changelog, which canonical was missing.

WillemHoman mentioned this pull request Aug 8, 2026

PAYMENTS-12054 Fix the CI bundler cache and the puma spec port collisions #46

Merged

WillemHoman force-pushed the PAYMENTS-11727-resque_latency_metrics_clear_queue branch from 6a2efb4 to fc80632 Compare August 8, 2026 07:04

WillemHoman force-pushed the PAYMENTS-11727-resque_latency_metrics_clear_queue branch from fc80632 to 4c30225 Compare August 20, 2026 07:06

WillemHoman marked this pull request as ready for review August 21, 2026 01:24

WillemHoman requested a review from a team as a code owner August 21, 2026 01:24

cursor Bot reviewed Aug 21, 2026

View reviewed changes

Comment thread lib/bigcommerce/prometheus/client.rb

WillemHoman force-pushed the PAYMENTS-11727-resque_latency_metrics_clear_queue branch from 4c30225 to 8740ec7 Compare August 21, 2026 04:14

cursor Bot reviewed Aug 21, 2026

View reviewed changes

Comment thread lib/bigcommerce/prometheus/client.rb