How to use Sentry for profiling a test suite

At Potloc one of our core values is learning, that's why each quarter the development team has a dedicated time to explore new things. This aptly named Dev Happiness Week allows us to tackle either a new pattern, open source project, write a blog post and so on.

One of my initial projects was to monitor our test suite. The more our test suite was growing quickly the more seconds were added to our CI. But without any monitoring on how long each test takes to run it was complicated to identify and speed up the slowest ones. Let's fix this by asking the following question:

What is the minimal valuable move to have a test profiling dashboard ?

We use Sentry for error tracking and they have a great feature for performance monitoring that allow you to track queries and get transactions duration.

Hence the following steps will show you how to twist the performance overview page of Sentry into a test suite monitoring. 🤓

Disclaimers: The following example assume that you use RSpec gem and that you already have a dedicated Sentry environment for it (eg: app-test-suite).

We would like to satisfy three specifications:

• Cover all of our test suite
• Don't flood our monitoring with unnecessary data (eg: unit tests that run in under 1 second)
• Make it easy to locate our slower tests

Cover all of our test suite

The easy one. Let's start by creating a profiling.rb file that will be run in our test suite, add an around hook and compute the elapsed time between the beginning of a run and the end.

#spec/support/config/profiling.rb

RSpec.configure do |config|
  config.around(:example) do |example|
    example_start = Time.now

    example.run

    example_end = Time.now
    elapsed_time_in_seconds = example_end - example_start
  end
end

Nice, we now cover the first bullet point of our specification.

Don't flood our monitoring with unnecessary data

The purpose here is to avoiding flooding Sentry when everything work as expected. We just want to send data when a test is slow or takes longer than expected.

We don't have the same expectations between a system test and a unit test. Hence we have to set a different thresholds accordingly:

#spec/support/config/profiling.rb

SLOW_EXECUTION = ["system"].freeze
MEDIUM_EXECUTION = ["integration", "export"].freeze
SLOW_EXECUTION_THRESHOLD = 6
MEDIUM_EXECUTION_THRESHOLD = 3
DEFAULT_EXECUTION_THRESHOLD = 1

RSpec.configure do |config|
  config.around(:example) do |example|
    category = spec_category(example)
    example_start = Time.now

    example.run

    example_end = Time.now
    elapsed_time_in_seconds = example_end - example_start
    if execution_time_in_seconds > threshold_for(category)
      print "Slow alert!"
    end
  end
end

# input: "./spec/integration/restaurants/owner_spec.rb:16"
# output: "integration"
def spec_category(example)
  location = example.metadata[:location].to_s
  location.gsub("./spec/", "")
          .scan(%r{^[^/]*})[0]
end

def threshold_for(category)
  case category
  when *SLOW_EXECUTION then SLOW_EXECUTION_THRESHOLD
  when *MEDIUM_EXECUTION then MEDIUM_EXECUTION_THRESHOLD
  else
    DEFAULT_EXECUTION_THRESHOLD
  end
end

Firstly we set our threshold constants, corresponding maximum execution times.
Then we add a spec_category method that allows us to identify the type of test, and we check if the runtime is lower or higher than expected.
If it does we print a beautiful message.

We are almost there! We just have to generate a custom Sentry transaction in order to populate the performance table with our profiling data.

#spec/support/config/profiling.rb

...

RSpec.configure do |config|
  config.around(:example) do |example|
    category = spec_category(example)
    example_start = Time.now
    transaction = Sentry::Transaction.new(op: category.upcase, hub: Sentry.get_current_hub)

    example.run

    ...

    if execution_time_in_seconds > threshold_for(category)       
      transaction.finish
    end

    ...

Our Sentry::Transaction takes 2 arguments:

• op : used for the name of the operation (eg: sql.query ). In our case we will populate it with the category of our spec.
• hub: Sentry requires an hub, we use the current. According to documentation "You can think of the hub as the central point that our SDKs use to route an event to Sentry"

By finishing our transaction we send our event to Sentry. From now on you should see your first tests appear on the performance dashboard.

Feel free to read Sentry documentation for a better understanding the performance table.

⚠️ By tweaking the performance dashboard of Sentry for our test suite we have to deal with the expected behaviour of Sentry. Such as send event when there is fail in your environnement

That's why it's necessary to add the following configuration in our Sentry test initializer.

#spec/support/config/sentry.rb

Sentry.init do |config|
  config.dsn = "https://4**************************************3"
  config.excluded_exceptions += ["Exception"]
end

In our context of profiling we won't send an event when a test fails on our CI. For avoiding noise and flooding you have to exclude all exceptions.

Make it easy to locate our slower tests

By default the transaction name corresponds to the name of the controller where the transaction has been run. In the screenshot above it shows that our test uses the method template in ChartsController. It's not really convenient to identify what test this concerns.
We need to tweak our transaction a little bit more:

#spec/support/config/profiling.rb

...

RSpec.configure do |config|
  config.around(:example) do |example|
    ...

    if execution_time_in_seconds > threshold_for(category) 
      assign_custom_transaction_name(example)
      transaction.finish
    end
  end
end

...

def assign_custom_transaction_name(example)
  Sentry.configure_scope do |scope|
    scope.set_transaction_name(example.metadata[:location])
  end
end

By using the configuration scope we are able to update our transaction name. According to documentation, "The scope will hold useful information that should be sent along with the event".

Here we assign our test path as the transaction name. That's it.
Run your test again and you should see

For the purpose of development we didn't add a guard clause so far, but you can check if you are on your CI environment before profiling your tests.

The entire profiling.rb class should look like this.

#spec/support/config/profiling.rb

SLOW_EXECUTION = ["system"].freeze
MEDIUM_EXECUTION = ["integration", "export"].freeze
SLOW_EXECUTION_THRESHOLD = 6
MEDIUM_EXECUTION_THRESHOLD = 3
DEFAULT_EXECUTION_THRESHOLD = 1

RSpec.configure do |config|
  if ENV["CI"]
    config.around(:example) do |example|
      category = spec_category(example)
      example_start = Time.now

      example.run

      example_end = Time.now
      elapsed_time_in_seconds = example_end - example_start

      if execution_time_in_seconds > threshold_for(category)         
        assign_custom_transaction_name(example)
        transaction.finish
      end
    end
  end
end

# input: "./spec/integration/restaurants/owner_spec.rb:16"
# output: "integration"
def spec_category(example)
  location = example.metadata[:location].to_s
  location.gsub("./spec/", "")
          .scan(%r{^[^/]*})[0]
end

def threshold_for(category)
  case category
  when *SLOW_EXECUTION then SLOW_EXECUTION_THRESHOLD
  when *MEDIUM_EXECUTION then MEDIUM_EXECUTION_THRESHOLD
  else
    DEFAULT_EXECUTION_THRESHOLD
  end
end

def assign_custom_transaction_name(example)
  Sentry.configure_scope do |scope|
    scope.set_transaction_name(example.metadata[:location])
  end
end

That's all, happy profiling ! 🎉

Interested in what we do at Potloc? Come join us! We are hiring 🚀