PAYMENTS-11727 Deliver metrics recorded inside Resque jobs

[WillemHoman]

Jira: PAYMENTS-11727

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
Touches Resque Worker#perform and the shared client delivery path (mutex, HTTP timeouts). Child flush is off by default so upgrades should not change job latency, but background sends now use short timeouts instead of Net::HTTP’s 60s defaults.

Overview
Stops forked Resque children from inheriting the parent’s undrained metric queue, which caused in-job observations to be dropped when exit! cut delivery short.

Always on: wrapping Resque::Worker#perform resets the client in the child (by pid) before after_fork hooks, so the child does not re-send the parent’s backlog.

Opt-in (PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED or a callable resque_child_flush_enabled, resolved in the parent before each fork): the child synchronously drains its own queue after the job. Off by default so a gem bump does not add per-observation HTTP on the job path.

The client now serializes delivery on a mutex, bounds connect/read/write and flush (20ms default), and logs abandoned/in-flight sends (flushing stdio so Resque children actually emit the warning). flush! returns :empty, :success, :timeout, or :error.

Adds unit coverage plus an opt-in fork integration job in CI (Ruby 3.4 + Redis).

^{Reviewed by Cursor Bugbot for commit 8740ec7. 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.}

[cursor]

Errors hide remaining abandoned metrics

Medium Severity

When drain fails mid-flush, the failed message is logged and flush! returns :error, but report_outcome skips :error and never mentions whatever is still queued. In a Resque child those leftover observations are destroyed by exit! with no abandoned-count warning, unlike the :timeout path that this reporting was written to cover.

Additional Locations (1)

• lib/bigcommerce/prometheus/client.rb#L171-L186

 

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

[Catsuko]

❓

Why do you need to do this? I saw the exporter already has some similar code that handles it and it doesn't seem like your code interacts with the socket but instead does its own request via #post_message.

[Catsuko]

❓
I saw the original client does a continual write to a connection rather than separate requests for each message.

Given we are operating under a pretty tight deadline, do you think the extra overhead of separate requests per metric will matter?

[Catsuko]

❓
Should these changes be opt-in since it is quite a jump from the previous Net HTTP defaults?

60 does seem too long but i worry that people updating the gem might start dropping metrics without realising even without using PROMETHEUS_RESQUE_CHILD_FLUSH_ENABLED.

[Catsuko]

💭
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.

[Catsuko]

❓

Would it be worth framing this option as experimental until we get a chance to get it running in production and ensuring the timeout values make sense under load?

[Catsuko]

💭

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]

💭 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:

• https://github.com/DataDog/dd-trace-rb
• https://github.com/newrelic/newrelic-ruby-agent

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