skip to content

A Ruby CSV export endpoint is slow; how would you use stackprof or vernier to find where the time goes, and which sampling mode would you choose?

level: seniorimportance: must knowfreq 40%

answer

  1. sample the stack, don't trace
  2. stackprof mode :wall vs :cpu
  3. raw: true for flame graphs
  4. vernier: threads, GVL, GC pauses
  5. wide frames at the top are hot

basics

~20 s

Sample a real export with stackprof in :wall mode, its default, to see waits as well as CPU; use :cpu for computation only. vernier adds threads, GVL and GC activity. Look for the widest self-time frames.

solid answer

~40 s

A sampling profiler interrupts the program at intervals and records the stack, so it shows where time is spent with little overhead. For an export endpoint I would start with **wall-clock** sampling, because a slow response may be waiting on the database rather than computing: `StackProf.run(mode: :wall, raw: true, out: "tmp/export.dump") { export }`, then `stackprof tmp/export.dump --text` for the top frames and `--method 'CSV#<<'` to zoom in; `raw: true` enables `--d3-flamegraph`. `mode: :cpu` hides waits and shows only computation once you know it is CPU-bound. **vernier** (`Vernier.profile(out: "export.json") { export }`) samples in wall mode too and adds threads, GVL activity, GC pauses and idle time, viewed in a Firefox-profiler-based viewer. Typical findings: one query per row, building the whole CSV string in memory, per-row formatting and GC time.

code

ruby · 5 lines
ruby
require "stackprof"

StackProf.run(mode: :wall, raw: true, out: "tmp/export.dump") do
  ExportJob.new(account_id: 42).call # the slow export, on realistic data
end

go deeper

for a junior

Recall that a sampling profiler records stacks at intervals and that stackprof and vernier are the common Ruby choices.

for a middle

Explain :wall versus :cpu modes, self versus total samples, and raw: true for stackprof flame graphs.

for a senior

Show the workflow on a slow endpoint: realistic data, wall mode first, zoom into hot methods, then choose between query, allocation and CPU fixes.

for a principal

Decide how the team profiles in production-like conditions, such as middleware behind a flag, and who reads the results.

## Sampling, not tracing A **sampling profiler** interrupts the running program at a fixed interval and records the current call stack. After thousands of samples, a method that appears in 30% of them used about 30% of the time. Overhead stays low because nothing happens between samples, which is why these tools are usable on realistic workloads. Two are standard for Ruby: - **stackprof** - a C-extension sampler that records Ruby stacks; results are read with its `stackprof` command. - **vernier** - a newer sampler (Ruby 3.2.1+) whose README lists tracking multiple threads, GVL activity, GC pauses and idle time; results open in a customised Firefox Profiler viewer. ## Choosing the mode stackprof's modes: | Mode | Samples on | Default interval | Use it when | |---|---|---|---| | `:wall` (default) | wall-clock timer | 1000 us | the endpoint may be waiting on I/O, locks or sleeps | | `:cpu` | CPU-time timer | 1000 us | you know it is CPU-bound and want only computation | | `:object` | object allocations | every allocation | you want to know which code allocates | | `:custom` | explicit `StackProf.sample` calls | - | you choose the sample points | For a slow HTTP response, **start with wall time**. If most samples sit in database-driver or socket frames, the fix is fewer or better queries, not faster Ruby. Switch to `:cpu` once waits are ruled out. vernier samples wall time by default and shows idle and GVL states explicitly, which helps when the app uses threads. ## Running it on the export 1. Reproduce with realistic data: a thousand-row export does not show the costs of a million-row one. 2. Profile a block: `StackProf.run(mode: :wall, raw: true, out: "tmp/export.dump") { ExportJob.new(params).call }`, or `Vernier.profile(out: "export.json") { ... }`. Both gems also ship a Rack middleware, `StackProf::Middleware` and `Vernier::Middleware`. 3. Read the top: `stackprof tmp/export.dump --text --limit 20` lists frames by **self** samples (time in the frame itself) and **total** samples (including callees). 4. Zoom: `stackprof tmp/export.dump --method 'CSV#<<'` shows callers, callees and per-line samples of one method. 5. Visualise: with `raw: true`, `stackprof --d3-flamegraph tmp/export.dump > flame.html` writes a flame graph; vernier's output opens with `vernier view` or in its web viewer. ## Reading the result for a CSV export In a flame graph, **width is the share of samples**; left-to-right order is not time (vernier's README says the same of its flame graph, and offers a separate stack chart where the x-axis is time). Look for wide plateaus near the top - frames with high self time. Common findings: - **Per-row queries** - many samples inside the database adapter, called from the row loop; - **Building the whole file in memory** - samples in String concatenation and in GC, and a growing heap; - **Per-row formatting** - time in date or number formatting repeated for every row; - **CSV generation itself** - `CSV#<<` and field quoting; note that `csv` is a bundled gem since Ruby 3.4, so a Bundler app lists it in the Gemfile; - **GC** - stackprof shows collections as GC frames unless `ignore_gc: true`; a large GC share points to allocation, which an allocation report then breaks down. ## Summary Reproduce with realistic data, sample in wall mode first, read self versus total samples, zoom into the hot method, then switch to `:cpu` or an allocation view once you know which kind of time dominates.

  • stackprof in :cpu mode shows the export as fast, but users wait 20 seconds; what is going on?
    `:cpu` samples only while the process uses CPU, so time spent waiting on the database, the network or a lock is invisible. Profile again in `:wall` mode, stackprof's default, or with vernier, which also marks idle and GVL time. The waiting frames will then show up.
  • What is the difference between self and total samples in a stackprof report?
    Self samples count stacks where the method was the innermost frame, so the time was spent in its own code. Total samples count every stack the method appears in, including time in methods it called. A method with high total but low self is a caller; high self marks where work actually happens.

A sampling profiler is like photographing a kitchen every few seconds during dinner service: no single photo explains anything, but if the cook is at the fryer in a third of them, the fryer is where the evening went.

saying these in an interview costs you the question

  • Tracing every method call gives more accurate results than sampling
  • stackprof's :cpu mode shows time spent waiting on the database
  • In a flame graph, left-to-right order is the order of execution
  • Profiling a ten-row export is representative of a million-row one
  • A method with high total samples is always where to optimise