TestProf III: guided and automated Ruby test profiling

We started this series more than six years ago, but the problems we discussed regarding slow Ruby/Rails tests—and solutions we proposed—still hold true today. Can you imagine that? We’ve gone forward two Rails versions and one Ruby version from back in 2018, but the best way to keep your tests fast is still by using let_it_be, instead of let / let!; and before_all, instead of before(:each). So, we’re not going to repeat ourselves. Instead, we’d like to talk about how TestProf and its usage patterns have evolved over time.

In this part, we’ll cover the following topics:

• TestProf playbook
• TestProf Autopilot
• More features and futures

Introducing the TestProf playbook

Over the years, we (Evil Martians) have worked on dozens of Rails applications, and, for each of those, the test suites got at least a bit of love attention (we’ve even had gigs focused solely on test performance). Unsurprisingly, the reasons for slowness and the way we approached these test suites were very similar, so we’ve come up with the following framework (or playbook):

• We start with some eye-profiling: checking the application’s configuration, looking through the Gemfile searching for known perpetrators.
• We continue with analyzing StackProf samples with Speedscope.
• Then, we kick into full gear with TestProf’s own profilers: TagProf, EventProf, FactoryProf, and the rest.

The full version of the TestProf playbook is available here: test-prof.evilmartians.io/playbook

Our playbook helps get started with test profiling. Still, it requires a bunch of manual operations to be conducted by a developer. Given that we deal with slow tests, profiling naturally results in long feedback loops. So, we started looking into ways to minimize human interactions and came up with the autopilot idea.

Automating profiling with TestProf Autopilot

Having something described as a formal process is the first step towards automation. So, after formalizing the playbook, we were ready to make this step. This is how the TestProf Autopilot was born.

TestProf Autopilot is a CLI tool (and a gem) that helps execute complex TestProf scenarios. You write a script in Ruby and execute it against your codebase. For example, this is how you can automate the generation and merging of StackProf reports to see the aggregated results:

# spec/.test-prof/stack_prof_scenario.rb

# First, profile the boot time
run :stack_prof, boot: true, sample: 10

save report, file_name: "stack_prof_boot"

# Then, generate multiple sampled profiles and aggregate the results
aggregate(3) { run :stack_prof, sample: 100 }

save report, file_name: "stack_prof_sample"

And then, you run the script via the auto-test-prof command:

bundle exec auto-test-prof -i spec/.test-prof/stack_prof_scenario.rb

Autopilot performs four runs and saves the reports to the specified locations—all without distracting you from other tasks you might have switched to knowing that profiling would take some time.

Since scenarios are Ruby scripts, you’re free to use all the power and expressiveness of the language to serve your profiling needs. Let me share another real-life scenario—selecting files responsible for >50% of the time spent in factories for a given group:

# spec/.test-prof/event_prof_scenario.rb

run :event_prof, event: "factory.create", top_count: 1000

total_run_time = report.raw_report["absolute_run_time"]
total_event_time = report.raw_report["total_time"]

threshold = 0.5 * total_run_time

sum = 0.0
sum_event = 0.0

top_groups = report.raw_report["groups"].take_while do |group|
  next false unless sum < threshold

  sum += group["run_time"]
  sum_event += group["time"]
  true
end

msg = <<~TXT
  Total groups: #{report.raw_report["groups"].size}
  Total times: #{total_event_time} / #{total_run_time}
  Selected groups: #{top_groups.size}
  Selected times: #{sum_event} / #{sum}

  Paths:

TXT

paths = top_groups.map { _1["location"] }

puts msg
puts paths.join("\n")

And this is how you run it:

$ bundle exec auto-test-prof -i spec/.test-prof/event_prof_scenario.rb \
  -c "bundle exec rspec spec/models"

Total groups: 497
Total time: 2210.41 / 2394.49
Selected groups: 26
Selected time: 1118.15 / 1199.34

Paths:

./spec/models/appointment_spec.rb:4
./spec/models/user_spec.rb:3
./spec/models/assessment_spec.rb:3
...

You can see that this scenario helped us narrow down optimization work to 26 files out of 497—just ~5% of all files were responsible for 50% of all run time!

Although it wasn’t a part of the original plan, Autopilot became especially useful for dealing with larger codebases, those where running the whole test suite using a single process would take hours. If you take a look in the playbook, you may notice that some steps require full test suite runs, e.g., TagProf analysis.

We already had the functionality to save reports in JSON format and merge them (see the aggregate example above), so we only needed to expose these features to the CLI. As a result, the --merge option was added:

$ auto-test-prof --merge tag_prof --reports tag_prof_*.json

Merging tag_prof reports at tag_prof_1.json, tag_prof_2.json, tag_prof_3.json

[TEST PROF] TagProf report for type

       type          time   factory.create    total  %total   %time           avg

      model     28:08.654        19:58.371     1730   56.44   46.23     00:00.976
    service     20:56.071        16:14.435      808   29.18   28.35     00:01.554
        api     04:48.179        03:54.178      214    7.32    4.78     00:01.346
        ...

But how can we collect the reports? Just run TestProf Autopilot on CI and store the reports as artifacts! Here is an example scenario:

run :tag_prof, events: ["factory.create"]

save report, file_name: "tag_prof_#{ENV["CI_NODE_INDEX"]}"

You may still need to download all the files manually, which is not ideal. One of the possible workarounds we’re considering adding in future releases is the #upload method which would store reports in the cloud (maybe, even TestProf Cloud 😉).

TestProf Autopilot has been an internal project for quite a while and has become our trusted companion when it comes to test optimization tasks. It’s still in (not-so) active development but nevertheless usable enough to be revealed to the public—so, please, give it a try and share your thoughts (and issues)!

Speaking of announcements, let’s see what else we’ve prepared for your in this fresh TestProf release.

More features and futures

TestProf hit v1.0 almost three years ago; it’s a stable and mature software. But maturity doesn’t mean we don’t have anything new to show you. Here are the highlights of the latest release, TestProf v1.3.0.

We introduced a brand new profiler—MemoryProf. It helps you identify examples and groups responsible for RSS usage spikes or a high number of object allocations. You may ask, “Why should we care about memory usage in tests?“. First, to optimize your CI infrastructure (self-hosted or not—it doesn’t matter, you still pay for it). Secondly, this kind of profiling can help you identify production memory issues, too. Give it a try and see what insights it reveals!

Another new feature we’re excited about is Vernier integration. Vernier is a next-generation Ruby sampling profiler with better multi-threading, GVL, and GC event support. We don’t know yet if it has some advantages in the context of tests profiling, but its compatibility with Firefox Profiler UI looks appealing. Here’s how I tried to find the cause of a sudden slow down in the test suite (spoiler: it was Sentry.capture_message):

So, what’s next for TestProf? We don’t have big plans for v2 (okay, I do, but no timeline yet). Instead, we’re focusing on expanding the TestProf universe and bringing new tests-oriented tools. We also released Mock Suey a year ago, a toolkit to make mocks more reliable and avoid false positives.

Next in line is a project with the codename ”Flakon”, which aims to help you deal with flaky tests.

Finally, we plan to further automate the TestProf playbook and provide something like test-prof-audit—an tool for analyzing your configuration and dependencies and suggesting optimizations (see logging and Wisper examples in the playbook).

Stay tuned and join the faster tests movement! (Or you can always support us!)

At Evil Martians, we transform growth-stage startups into unicorns, build developer tools, and create open source products. If you’re ready to engage warp drive, give us a shout!