Report process-wide GVL wait from the Ruby sampler (!251874) · Merge requests · GitLab.org / GitLab

What does this MR do and why?

GVLTools::GlobalTimer is a single process-wide counter. On every thread's RESUMED event the same wait duration is added both to that thread's local timer and to the global one, so the endpoint difference of the global counter is already the total thread-seconds of GVL waiting in a process, with each wait event present exactly once.

Two places differenced that process-wide counter over a single unit of work:

sidekiq_gvl_process_wait_seconds, incremented once per job by the per-job difference.
gvl_process_wait_s in the structured log payload, from the per-request or per-job difference.

Job and request windows on other threads overlap in wall-clock time, so one wait event was billed once per window that happened to be open, and the accumulated total ran hot by roughly the thread count.

This reads the counter once per process from RubySampler instead, as ruby_gvl_wait_seconds_total. Successive readings telescope, so the total is exact regardless of the sampling interval. RubySampler already runs in both Puma and Sidekiq, so the metric will cover both once the timers are enabled in Puma. As of this MR, only Sidekiq enables them.

The per-thread timer needs no fix, because a wait event belongs to exactly one thread and therefore one unit of work. sidekiq_gvl_thread_wait_seconds and the gvl_thread_wait_s log field are kept as they are.

Reproducer

Save as /tmp/gvl_reproducer.rb and run ruby /tmp/gvl_reproducer.rb (needs Ruby 3.2+; no Rails boot required).

gvl_reproducer.rb

require "gvltools"
MS = ->(ns) { (ns / 1_000_000.0).round(1) }
def fib(n) = n < 2 ? n : fib(n - 1) + fib(n - 2)

# Alternates blocking regions with CPU work, so the thread repeatedly releases
# and re-acquires the GVL the way a real job does around DB/Redis/Gitaly calls.
def job = 30.times { sleep 0.002; fib(21) }

GVLTools::GlobalTimer.enable
GVLTools::LocalTimer.enable

# CHECK 1 -- the counter itself double-counts nothing.
# On each RESUMED event the same wait is added to the thread's local timer and
# to the global one, so the global endpoint delta must equal the sum of every
# thread's own local wait. That makes the endpoint delta the physical total.
def identity_check(concurrency)
  locals = {}
  before = GVLTools::GlobalTimer.monotonic_time
  concurrency.times.map { |i| Thread.new { job; locals[i] = GVLTools::LocalTimer.monotonic_time } }.each(&:join)
  [GVLTools::GlobalTimer.monotonic_time - before, locals.values.sum]
end

# CHECK 2 -- summing per-job deltas of that counter inflates by ~concurrency.
# Windows are barrier-aligned so each brackets the same set of wait events;
# every open window bills every event, which is the double count.
def overcount_check(concurrency)
  mutex = Mutex.new
  per_job = 0
  started = 0
  gate = Mutex.new
  cond = ConditionVariable.new

  before = GVLTools::GlobalTimer.monotonic_time
  concurrency.times.map do
    Thread.new do
      gate.synchronize do
        started += 1
        cond.broadcast if started == concurrency
        cond.wait(gate) while started < concurrency
      end
      g_before = GVLTools::GlobalTimer.monotonic_time
      job
      mutex.synchronize { per_job += GVLTools::GlobalTimer.monotonic_time - g_before }
    end
  end.each(&:join)

  [GVLTools::GlobalTimer.monotonic_time - before, per_job]
end

overcount_check(2) # warm up

puts "CHECK 1 -- global counter == sum of each thread's own local wait"
global, locals = identity_check(8)
puts format("  endpoint delta %sms vs sum of locals %sms -> error %.4f%%\n\n",
  MS[global], MS[locals], (locals - global).abs / global.to_f * 100)

puts "CHECK 2 -- sum of per-job deltas vs that physical total"
puts "   C | physical total | sum of per-job deltas | ratio"
puts "  ---+----------------+-----------------------+-------"
[2, 4, 8, 12].each do |c|
  physical, summed = overcount_check(c)
  puts format("  %2d | %11sms | %18sms | %5.2fx", c, MS[physical], MS[summed], summed.to_f / physical)
end

Output on Ruby 3.3.11, gvltools 0.4.0:

CHECK 1 -- global counter == sum of each thread's own local wait
  endpoint delta 454.8ms vs sum of locals 452.4ms -> error 0.5128%

CHECK 2 -- sum of per-job deltas vs that physical total
   C | physical total | sum of per-job deltas | ratio
  ---+----------------+-----------------------+-------
   2 |         2.5ms |                4.8ms |  1.94x
   4 |         6.3ms |               18.6ms |  2.96x
   8 |       447.3ms |             3511.0ms |  7.85x
  12 |      1536.6ms |            18130.2ms | 11.80x

Check 1 establishes that the endpoint difference is the physical total, so nothing about the argument depends on threads running in parallel; they do not. Check 2 shows the summation inflating by the thread count on top of it.

Worth noting that GVL wait legitimately exceeds wall-clock time, because waiting is concurrent even though execution is not. The endpoint difference represents that correctly. Only the summation was wrong.

Metric and log field changes

Name	Change
`ruby_gvl_wait_seconds_total`	Added. Gauge, one series per process, cumulative seconds.
`sidekiq_gvl_process_wait_seconds`	Removed.
`gvl_process_wait_s` (log field)	Removed.
`sidekiq_gvl_thread_wait_seconds`	Unchanged.
`gvl_thread_wait_s` (log field)	Unchanged.

The two removed items sit behind the enable_sidekiq_gvl_metrics ops flag, which is still rolling out, and sidekiq_gvl_process_wait_seconds was never documented, so no dashboard should depend on it.

Nothing enables the GVL timers in Puma yet, so ruby_gvl_wait_seconds_total reports only from Sidekiq processes. !251880 adds Puma enablement behind the enable_puma_gvl_metrics ops flag.

References

Rollout issue for the ops flag: #577455
Merge request that added the Sidekiq GVL instrumentation: !209086 (merged)
Merge request that adds Puma GVL timer enablement, targeting this MR: !251880

Screenshots or screen recordings

Not applicable, no user interface changes.

How to set up and validate locally

Enable the ops flag in the Rails console:

Feature.enable(:enable_sidekiq_gvl_metrics)

Restart Sidekiq so it picks up the branch, then enqueue a job that does some real work:

gdk restart rails-background-jobs

# rails console
20.times { ProjectCacheWorker.perform_async(Project.first.id, [], [:repository_size]) }

The thread field is still logged. Confirm gvl_thread_wait_s is present:

grep -o '"gvl_thread_wait_s":[0-9.e-]*' log/sidekiq.log | tail -5

The process field is gone from the logs. This should return nothing:
```
grep -c 'gvl_process_wait_s' log/sidekiq.log
```
The new sampler metric is exported. RubySampler runs every 60s, so allow a minute after Sidekiq boots:
```
curl -s http://gdk.test:3807/metrics | grep ruby_gvl_wait_seconds_total
```
Expect one series per Sidekiq process, increasing on repeated calls while jobs run:
```
ruby_gvl_wait_seconds_total{pid="sidekiq"} 0.031482
```

The old process metric is gone. This should return nothing:

curl -s http://gdk.test:3807/metrics | grep sidekiq_gvl_process_wait_seconds

The per-job thread histogram still works:

curl -s http://gdk.test:3807/metrics | grep sidekiq_gvl_thread_wait_seconds_count

Disabling the flag stops the new metric. Turn it off, wait for the next sample, and confirm the value freezes rather than growing:
```
Feature.disable(:enable_sidekiq_gvl_metrics)
```

MR acceptance checklist

Evaluate this MR against the MR acceptance checklist. It helps you analyze changes to reduce risks in quality, performance, reliability, security, and maintainability.

Edited Sep 02, 2026 by Hordur Freyr Yngvason

Report process-wide GVL wait from the Ruby sampler