Stop guessing: profiling Ruby properly
Benchmarking a suspicion confirms the suspicion. A sampling profiler tells you where the time actually went.
The usual approach to a slow endpoint is to guess, wrap the guess in a timer, and measure it. It confirms the guess is slow. It says nothing about whether it is the problem.
Sampling versus tracing
A tracing profiler instruments every method call. It is exact and it changes the program's performance so much that the profile describes a different program.
A sampling profiler interrupts periodically and records the stack. It is statistical rather than exact, and cheap enough to run against production traffic — which is where the interesting slowness lives, because it depends on real data volumes and cache states.
For finding a bottleneck, sampling wins almost every time. Exactness is not what you need; you need to know which branch of the stack holds the time.
Read total, then self
Two numbers matter and they answer different questions.
Total time includes everything a method called. A controller action has high total time by definition — it called everything.
Self time is spent in that method's own code. A method with high self time is doing the work itself. That is where an optimisation changes something.
Reading total time and optimising the top entry is the classic mistake: you end up staring at a framework entry point that is merely the root of the tree.
High total time tells you where to look next. High self time tells you where to work.
Wall versus CPU
Wall time is elapsed time. CPU time is time actually executing.
A method with high wall and low CPU is waiting — on a database, an API, a disk. No amount of Ruby optimisation helps; the fix is fewer round trips, or concurrency.
High CPU means you are genuinely computing, and there the usual suspects are allocation, serialisation, and doing in Ruby what the database could do in SQL.
Profiling only wall time makes network calls look like hot code. Profiling only CPU makes them invisible. You want both.
Allocation is its own profile
Ruby's garbage collector is fast, and it still costs. A method allocating hundreds of thousands of short-lived objects shows up as diffuse GC time rather than as a hotspot, which makes it hard to find in a time profile.
An allocation profile — which lines create the most objects — points straight at it. The fixes are usually unglamorous: build fewer intermediate arrays, avoid string concatenation in loops, stop instantiating models you only read one column from.
Profile the environment you care about
Development has different data, no cache warmth, and code reloading. Its profile describes development.
Run the profiler in an environment that resembles production, on data that resembles production, and prefer a real request to a synthetic loop. A benchmark of one method called a million times measures something no user will ever experience.