Improve RSpec running speed with TestProf and RubyProf

If you are a RoR programmer, you must be familiar with terms like Unit test, BDD, or RSpec. Today I will not go into each of the above terms, but will introduce you to a great tool for those who have written RSpec, projects that have used RSpec to run tests in their CI pipeline – that is TestProf. Surely you have also seen projects that have a huge amount of RSpec code and run a lot of time, right, and you probably had the thought of wanting to smash all that RSpec code to write. From the beginning, hopefully its running speed will be better, but sometimes your project is busy and you don’t have time to do it, and you don’t know the core cause of RSpec. Your project is slow to come from. My introduction today will help you overcome all the difficulties with TestProf.

Introduction to TestProf

TestProf is a collection of RSpec performance analysis tools in a single gem that helps you find the core reason why your RSpec is slow by providing:

• A convenient method to run the ruby ​​profiler with the ruby-prof gem, all you need is to install the ruby-prof gem and use the test-prof ‘s built test-prof without having to fix too much code.
• Factories use analysis tool to generate test data is effective or not.
• Event profile – analyze what test run times are typically used.

Along with such great analysis tools, test-prof also makes recipes, or can be called, replacement helper to improve our RSpec code, helping them run faster without having to. Excessive modification of the existing code structure. The figure below summarizes all the tools that test-prof offers. In addition, test-prof also supports performance analysis for Minitest, very convenient for projects that write unit tests without using RSpec.

To install test-prof , we only need to declare in Gemfile:

In the next section, we will go into detail about the tools mentioned above.

Exploit information by type of test case

Finding out right away the cause of RSpec’s underperformance is very difficult, the first thing to do is to determine which part of the test cases we are writing takes up the most runtime .

To answer that question, we will use the Tag Profiler (TagProf) of test-prof , TagProf is a simple profiler that collects RSpec runtime performance of test case types classified by their tag. Normally, rspec-rails will automatically divide the test cases by the default tag by controller, model, helper …. When writing tests, we must also assign tags to them by default without notice.

For example:

With TagProf, we can know the information about the runtime of each test type, what percentage of the total run time, how many test cases for each type of test, and how many percent of the total. Test case, what is the average time to run a case. All we have to do is set the environment variable before we run rspec:

We can obtain the following result:

Note that in the above example, we use the classification by type , we can define the test run by another tag, for example the function such as:

We can also generate a report with a visual html format by running rspec as follows:

We can obtain a report file as follows:

Determine which method takes up the most runtime

Once we have identified which components are running slow, we can simply run tests with that type of tag and continue to analyze where the main cause of that test is running slow. This is where ruby-prof shines, of course with the help of test-prof , first of all the ruby-prof integration requires us to declare it in the Gemfile.

If anyone who has ever used this gem to test the method’s runtime knows to measure such results, we have to manually add code before and after each code, but work with test-prof then we don’t need to do that. ruby-prof can run in two modes, global and per-example, with global mode, we just need to run rspec as follows without having to edit code:

To run the per-example, we add the shared context option after the examples that need the profile:

After running, we get the following results, the runtime of each method when running the test is arranged in descending order:

In the output file (the path will be printed to the screen after the rspec is finished), there will be detailed explanations about each column in the results above, but here I will give the basic definition:

• %self percent of the time that method runs on the total time.
• calls method how many times.
• name method name and it is called from class or instance of any class.

ruby-prof can run in two modes, wall and cpu , where wall time measures the actual elapsed time when the method is called, and cpu time measures how long cpu processes that method (i.e. if there is another process processed by cpu, that time will not be recorded in the result). Personally, I find the default wall time more useful because it measures how long we humans have to wait to run rspec. As we can see in the above example, the bc_crypt method is called the least but it takes the most time, allowing us to deduce that the code related to password encryption can slow down the rspec, thereby taking measures to improve it. goodness.

Some common methods can be removed from the profiling list by adding the following config to rails_helper.rb :

test-prof default enables the removal of common method, to disable this function we need to add the following config:

Determine which events take place the most

EventProf is a test-prof tool that collects the most happening events. It works like the notification and instrumentation mechanism of ActiveSupport (if anyone does not know, you can find out here ). It basically works like when we run rspec with the -p option, which will print out 5 or 10 slowest running test suites, but instead we will track one or more events.

test-prof supports all the events that ActiveSupport pre-defined such as sql.active_record , render_template.action_view , … (read more here ). In addition, it also supports a few other custom events such as factory.create (track events that generate data through Factories), sidekiq.inline , sidekiq.jobs (track events related to running sidekiq jobs, inline).

To run EventProf, we also don’t need to edit the code at all (the great thing about test-prof is that we don’t need to edit too much code to run) just run the rspec command like this:

We can also measure multiple events by providing a list of events separated by commas , .

We will obtain the following result:

The results include information such as, the runtime of the event on the total time, the number of times the event occurred, and the slowest test suites and test cases.

By default, EventProf collects parameters based on test suite, if you want EventProf to crawl on each example, we need a config like this:

Or add variable EVENT_PROF_EXAMPLES=1 .

Now that we have learned some ways to gather information about RSpec performance, you can now partly find out what is the cause of your project’s current test cases slowdown. I will spend analyzing performance of creating test data, recipes improving test case in another part.

The article is referenced at:

https://test-prof.evilmartians.io/#/ https://evilmartians.com/chronicles/testprof-a-good-doctor-for-slow-ruby-tests https://guides.rubyonrails.org/active_support_instrumentation .html https://ruby-prof.github.io/