Draft: Instrument GVL wait time in Puma processes

What does this MR do and why?

The GVL timers were only ever enabled from the Sidekiq server middleware, so gvl_thread_wait_s appeared in Sidekiq logs alone. The rest of the plumbing is already runtime-neutral:

  • Gitlab::Middleware::RequestContext takes the thread timer baseline for every Rack request.
  • InstrumentationHelper#add_instrumentation_data already writes the field into both the Rails (lograge) and Grape log payloads.

So this only reconciles the timers from Gitlab::Middleware::RequestContext as well. Web and API request logs then carry gvl_thread_wait_s, and RubySampler reports ruby_gvl_wait_seconds from Puma workers.

The toggle moves into Gitlab::Instrumentation::Gvl because both call sites have to enable the same pair: the thread timer feeds the log field, and the process timer feeds ruby_gvl_wait_seconds.

Why a separate ops flag

Puma gets enable_puma_gvl_metrics rather than sharing enable_sidekiq_gvl_metrics. The gem documents a 1-5% slowdown on a saturated multi-threaded process, and web latency and background job throughput deserve separate rollout control. A single :current_pod-scoped flag cannot express "web pods only", because a percentage rollout over pods is not selectable by runtime.

Reading the numbers

GVL wait counts thread-seconds, not elapsed time, so a process with several busy threads accumulates it faster than real time. Both timeslice preemption of CPU-bound work and re-acquisition after a blocking region contribute. Measured locally with four purely CPU-bound threads on Ruby 3.3: each accumulated ~2.23s of wait over 3.5s of wall clock, 9.0s in total, which is the ~3/4-of-the-time-waiting you would predict for four threads sharing one lock.

References

Screenshots or screen recordings

Not applicable, no user interface changes.

How to set up and validate locally

  1. Enable the ops flag in the Rails console:

    Feature.enable(:enable_puma_gvl_metrics)
  2. Restart Puma so it picks up the branch, and give it a moment to boot:

    gdk restart rails-web
  3. Make a few requests. Any page works; /-/liveness avoids needing Gitaly:

    for i in $(seq 1 5); do curl -s -o /dev/null -w "%{http_code} " https://gdk.test:3000/-/liveness; done
  4. Web request logs carry the field. In development the lograge output is development_json.log:

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

    Expected, one entry per request:

    "gvl_thread_wait_s":0.008686
    "gvl_thread_wait_s":2.9e-05
  5. API request logs carry the field too, through the Grape logger rather than lograge:

    curl -s -o /dev/null https://gdk.test:3000/api/v4/projects?per_page=1
    grep -o '"gvl_thread_wait_s":[0-9.e-]*' log/api_json.log | tail -3
  6. The sampler now reports from Puma. RubySampler runs every 60s, so allow a minute after boot:

    curl -s https://gdk.test:3000/-/metrics | grep ruby_gvl_wait_seconds

    Expected, one series per Puma worker, increasing on repeated calls:

    ruby_gvl_wait_seconds{pid="puma_0"} 0.020961
    ruby_gvl_wait_seconds{pid="puma_1"} 0.018675
  7. The process field is still absent from web logs, as removed in the parent MR. This should return nothing:

    grep -c 'gvl_process_wait_s' log/development_json.log log/api_json.log
  8. Disabling the flag stops the instrumentation without a restart. The flag is reconciled per request, so the field disappears from log lines written after the next request:

    Feature.disable(:enable_puma_gvl_metrics)
    curl -s -o /dev/null https://gdk.test:3000/-/liveness
    tail -1 log/development_json.log | grep -c gvl_thread_wait_s   # expect 0
  9. Sidekiq is unaffected. With enable_sidekiq_gvl_metrics off and enable_puma_gvl_metrics on, Sidekiq job logs should still have no gvl_thread_wait_s, confirming the two flags are independent.

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 by Hordur Freyr Yngvason

Merge request reports

Loading
Loading