From slow tests to slow production: Debugging with Stackprof<br>Articles<br>Culture<br>Careers<br>Aha!'s GitHub organizationFind our posts on Hacker NewsAha! engineering blog RSS feed<br>Aha! Develop is the agile tool that links strategy to delivery.

Learn more

Jeremy Stuckey · 2026-08-13 · engineering<br>From slow tests to slow production: Debugging with Stackprof<br>One morning, a developer announced in our Slack channel that some tests were failing on our main branch. The cause of the failures was not obvious. No recent PRs seemed related, and neither the code nor the tests had changed in a long time. The tests seemed to be timing out after several minutes rather than failing outright. All this piqued my curiosity, and I decided to take a look. It turned out we had just caught a massive potential performance degradation. This is how I nailed down the root cause.

The initial pass

The first step was to look into the CI logs. I focused on one of the tests that ran for two minutes before failing. This was a Capybara test, which can be on the slower side, but two minutes seemed like an outlier. Fortunately, we track the average execution time of our tests and use the data to split tests into buckets for parallel execution. The test in question normally took 20 seconds to finish — so it was suddenly six times slower.

I ran the test locally to see if I could reproduce it, and sure enough, the test hung for about a minute and a half at one point. I started setting breakpoints in the code so I could step through and locate the source of the stall. I eventually landed on a method that was creating a bunch of example data. Were these database queries slow? The logs said no, but they did show a flurry of Active Record callbacks. Sprinkling breakpoints across callbacks sounds about as fun as cleaning up glitter after arts and crafts, so a change of strategy was in order.

Profiling with Stackprof

The next tool I reached for was a sampling profiler called Stackprof. It takes snapshots of the call stack on an interval and writes that data to a file for further analysis. Sampling profilers are generally quick with low overhead, which is useful for not slowing down the already slow test. The code change looked like this:

before do<br>StackProf.start(mode: :wall, raw: true)<br>end

after do<br>StackProf.stop<br>StackProf.results('/tmp/stackprof.dump')<br>end<br>Here, RSpec hooks wrap the spec in a Stackprof call. We are using the wall clock mode so that I/O time is included in addition to CPU time (I figured a slow test was likely waiting on I/O). We also include extra raw data, which is required to generate flame graphs (more on this below). We then tell Stackprof where to write the results.

After running the test and collecting the profiling data, we can analyze the results using Stackprof commands. These are the results as simple text:

$ bundle exec stackprof /tmp/stackprof.dump --text

Mode: wall(1000)<br>Samples: 123483 (1.09% miss rate)<br>GC: 691 (0.56%)<br>TOTAL (pct) SAMPLES (pct) FRAME<br>87774 (71.1%) 87774 (71.1%) Kernel#sleep<br>28736 (23.3%) 28736 (23.3%) IO#wait_readable<br>2062 (1.7%) 2062 (1.7%) PG::Connection#exec<br>516 (0.4%) 516 (0.4%) TCPSocket#initialize<br>394 (0.3%) 394 (0.3%) (marking)<br>295 (0.2%) 295 (0.2%) (sweeping)<br>163 (0.1%) 163 (0.1%) OpenSSL::SSL::SSLSocket#connect_nonblock<br>111 (0.1%) 111 (0.1%) IO#write<br>3588 (2.9%) 93 (0.1%) Class#new<br>90 (0.1%) 90 (0.1%) Kernel#methods

... more<br>The test spent 71% of its time sleeping! This is a Capybara test, so of course it sleeps a lot. It has to wait for pages to load and DOM to settle. Even so, 71% is a lot of sleep time, so I dug in further. Here, we can see the breakdown of Kernel#sleep callers:

$ bundle exec stackprof /tmp/stackprof.dump --method 'Kernel#sleep'

Kernel#sleep (:1)<br>samples: 87774 self (71.1%) / 87774 total (71.1%)<br>callers:<br>87392 ( 99.6%) Redlock::Client#try_lock_instances<br>251 ( 0.3%) Selenium::WebDriver::SocketPoller#with_timeout<br>131 ( 0.1%) Capybara::Node::Base#synchronize<br>Nearly all of the sleep time was spent in the Redlock::Client#try_lock_instances method. This turned out to be the smoking gun. Unfortunately, I was not familiar with how Redlock was used in our application. Even though the answer was staring me in the face, I needed more convincing.

Checking the flame graphs

I decided to examine the profiling results in a different way by using a flame graph. Stackprof can generate one with the command:

$ bundle exec stackprof /tmp/stackprof.dump --d3-flamegraph > /tmp/flamegraph.html<br>Open the generated HTML file in a browser:

Some tips for interpreting a flame graph:

Each horizontal bar represents a frame of the stack.

The width of the bar represents how long the program spent in that frame.

The height represents the depth of the call stack.

The root of the stack is at the bottom of the graph.

The rows diverge as methods are called.

The colors are arbitrarily assigned within a palette and are just for visual separation.

A good technique for finding the bottleneck is to...