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 🚀
Top comments (0)