How to use Sentry for profiling a test suite
Tags: sentry, rspec, profiling, ruby
Published: 2021-09-20 20:11:37

At [Potloc](https://www.potloc.com/) 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](https://sentry.io/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. :nerd_face:

*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] (https://relishapp.com/rspec/rspec-core/v/2-0/docs/hooks/around-hooks) and compute the elapsed time between the beginning of a run and the end.

```ruby
#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:

```ruby
#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.

```ruby
#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](https://github.com/getsentry/sentry-ruby/blob/3ddb146ed2feaf2d2c078c979629ab567a2701d8/sentry-ruby/spec/sentry/transaction_spec.rb#L10) (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](https://docs.sentry.io/platforms/ruby/enriching-events/scopes/) *"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.

![Alt Text](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/vmmqxkt0k5u84e1ywz24.png)

Feel free to read Sentry [documentation](https://docs.sentry.io/product/performance/metrics/) for a better understanding the performance table.

:warning: 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.

```ruby
#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:

```ruby
#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](https://docs.sentry.io/platforms/ruby/enriching-events/scopes/) 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

![Alt Text](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/esl8bq3d6w1elkkrjonj.png)

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.

```ruby
#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 ! :tada:

Interested in what we do at [Potloc](https://www.potloc.com/)? Come join us! We are [hiring](https://jobs.lever.co/Potloc) 🚀