EventProf

EventProf collects instrumentation (such as ActiveSupport::Notifications) metrics during your test suite run.

It works very similar to rspec --profile but can track arbitrary events.

Example output:

[TEST PROF INFO] EventProf results for sql.active_record

Total time: 00:00.256 of 00:00.512 (50.00%)
Total events: 1031

Top 5 slowest suites (by time):

AnswersController (./spec/controllers/answers_controller_spec.rb:3) – 00:00.119 (549 / 20) of 00:00.200 (59.50%)
QuestionsController (./spec/controllers/questions_controller_spec.rb:3) – 00:00.105 (360 / 18) of 00:00.125 (84.00%)
CommentsController (./spec/controllers/comments_controller_spec.rb:3) – 00:00.032 (122 / 4) of 00:00.064 (50.00%)

Top 5 slowest tests (by time):

destroys question (./spec/controllers/questions_controller_spec.rb:38) – 00:00.022 (29) of 00:00.064 (34.38%)
change comments count (./spec/controllers/comments_controller_spec.rb:7) – 00:00.011 (34) of 00:00.022 (50.00%)
change Votes count (./spec/shared_examples/controllers/voted_examples.rb:23) – 00:00.008 (25) of 00:00.022 (36.36%)
change Votes count (./spec/shared_examples/controllers/voted_examples.rb:23) – 00:00.008 (32) of 00:00.035 (22.86%)
fails (./spec/shared_examples/controllers/invalid_examples.rb:3) – 00:00.007 (34) of 00:00.014 (50.00%)

Instructions

Currently, EventProf supports only ActiveSupport::Notifications

To activate EventProf with:

RSpec

Use EVENT_PROF environment variable set to event name:

# Collect SQL queries stats for every suite and example
EVENT_PROF='sql.active_record' rspec ...

You can track multiple events simultaneously:

EVENT_PROF='sql.active_record,perform.active_job' rspec ...

Minitest

Use EVENT_PROF environment variable set to event name:

# Collect SQL queries stats for every suite and example
EVENT_PROF='sql.active_record' rake test

or use CLI options as well:

# Run a specific file using CLI option
ruby test/my_super_test.rb --event-prof=sql.active_record

# Show the list of possible options:
ruby test/my_super_test.rb --help

Using with Minitest::Reporters

If you're using Minitest::Reporters in your project you have to explicitly declare it in your test helper file:

require 'minitest/reporters'
Minitest::Reporters.use! [YOUR_FAVORITE_REPORTERS]

NOTICE

When you have minitest-reporters installed as a gem but not declared in your Gemfile make sure to always prepend your test run command with bundle exec (but we sure that you always do it). Otherwise, you'll get an error caused by Minitest plugin system, which scans all the entries in the $LOAD_PATH for any minitest/*_plugin.rb, thus initialization of minitest-reporters plugin which is available in that case doesn't happens correctly.

See Rails guides for the list of available events if you're using Rails.

If you're using rom-rb you might be interested in profiling 'sql.rom' event.

Configuration

By default, EventProf collects information only about top-level groups (aka suites), but you can also profile individual examples. Just set the configuration option:

TestProf::EventProf.configure do |config|
  config.per_example = true
end

Or provide the EVENT_PROF_EXAMPLES=1 env variable.

Another useful configuration parameter – rank_by. It's responsible for sorting stats – either by the time spent in the event or by the number of occurrences:

EVENT_PROF_RANK=count EVENT_PROF='instantiation.active_record' be rspec

See event_prof.rb for all available configuration options and their usage.

Using with RSpecStamp

EventProf can be used with RSpec Stamp to automatically mark slow examples with custom tags. For example:

EVENT_PROF="sql.active_record" EVENT_PROF_STAMP="slow:sql" rspec ...

After running the command above the slowest example groups (and examples if configured) would be marked with the slow: :sql tag.

Custom Instrumentation

To use EventProf with your instrumentation engine just complete the two following steps:

• Add a wrapper for your instrumentation:

# Wrapper over your instrumentation
module MyEventsWrapper
  # Should contain the only one method
  def self.subscribe(event)
    raise ArgumentError, "Block is required!" unless block_given?

    ::MyEvents.subscribe(event) do |start, finish, *|
      yield (finish - start)
    end
  end
end

• Set instrumenter in the config:

TestProf::EventProf.configure do |config|
  config.instrumenter = MyEventsWrapper
end

Custom Events

"factory.create"

FactoryGirl provides its own instrumentation ('factory_girl.run_factory'); but there is a caveat – it fires an event every time a factory is used, even when we use factory for nested associations. Thus it's not possible to calculate the total time spent in factories due to the double calculation.

EventProf comes with a little patch for FactoryGirl which provides instrumentation only for top-level FactoryGirl.create calls. It is loaded automatically if you use "factory.create" event:

EVENT_PROF=factory.create bundle exec rspec

Also supports Fabrication (tracks implicit and explicit Fabricate.create calls).

"sidekiq.jobs"

Collects statistics about Sidekiq jobs that have been run inline:

EVENT_PROF=sidekiq.jobs bundle exec rspec

NOTE: automatically sets rank_by to count ('cause it doesn't make sense to collect the information about time spent – see below).

"sidekiq.inline"

Collects statistics about Sidekiq jobs that have been run inline (excluding nested jobs):

EVENT_PROF=sidekiq.inline bundle exec rspec

Use this event to profile the time spent running Sidekiq jobs.

Profile arbitrary methods

You can also add your custom events to profile specific methods (for example, after figuring out some hot calls with RubyProf or StackProf).

For example, having a class doing some heavy work:

class Work
  def do_smth(*args)
    # do something
  end
end

You can profile it by adding a monitor:

# provide a class, event name and methods to monitor
TestProf::EventProf.monitor(Work, "my.work", :do_smth)

And then run EventProf as usual:

EVENT_PROF=my.work bundle exec rake test

You can also provide additional options:

• top_level: true | false (defaults to false): defines whether you want to take into account only top-level invocations and ignore nested triggers of this event (that's how "factory.create" is implemented)
• guard: Proc (defaults to nil): provide a Proc which could prevent from triggering an event: the method is instrumented only if guard returns true; guard is executed using instance_exec and the method arguments are passed to it.

For example:

TestProf::EventProf.monitor(
  Sidekiq::Client,
  "sidekiq.inline",
  :raw_push,
  top_level: true,
  guard: ->(*) { Sidekiq::Testing.inline? }
)

You can add monitors on demand (i.e. only when you want to track the specified event) by wrapping the code in TestProf::EventProf::CustomEvents.register method:

TestProf::EventProf::CustomEvents.register("my.work") do
  TestProf::EventProf.monitor(Work, "my.work", :do_smth)
end

# Then call `activate_all` with the provided event
TestProf::EventProf::CustomEvents.activate_all(TestProf::EventProf.config.event)

The block is evaluated only if the specified event is enabled with EventProf.