A tale about investigating why a test was still slow

Recently I posted about some of the things I learned in regards to profiling RSpec tests. In that post I focused on the techniques that can be used. In this post I’ll show you a specific example in which some those techniques were useful.

A couple of days ago I stumbled into a test using Factory Girl’s build method.

I noticed that the method being tested was not querying the database so I swapped build with build_stubbed since build_stubbed does not persist the associated records.

The cardinal rule of performance optimisations is to always be benchmarking so, I ran the tests again to see the impact of the changes.

To my surprise I noticed that the tests still took the same time to run even though I had removed database access from one of them.

In order to figure out what was happening I ran stackprof.

This shows that build_stubbed was still inserting records in the database (notice the ActiveRecord::ConnectionAdapters::PostgreSQL lines in the stackprof). The flame graph below also shows that ActiveRecord::Transactions#save! was invoked a bunch of times.

build_stubbed first flamegraph

This led me to conclude that there probably was a problem in how the factories were written.

The factory is actually creating the associated record irrespectively of the build strategy due to the line user{ create(:user_b, :name => "James") }. That line should have instead been written with an association so that Factory Girl can decide on which strategy to use.

Running the benchmarks again allows us to see the effect of the change.

The build_stubbed example is one order of magnitude faster than the build example and the stackprof report shows less time is spent in database land. The flame graph below shows that ActiveRecord::Transactions#save! is no longer invoked.

build_stubbed second flamegraph