Rails 6 EventProf Empty

[philipbjorge]

Tell us about your environment

Ruby Version: 2.6.5

Framework Version (RSpec, Minitest, FactoryGirl, Rails, whatever): RSpec 3.8, Rails 6.0.2.1

TestProf Version: 0.11.3

What did you do?

Ran env EVENT_PROF_TOP=3 EVENT_PROF_EXAMPLES=1 EVENT_PROF='factory.create,perform.active_job,sql.active_record' bundle exec rspec spec/system

What did you expect to happen?

I expected to see EventProf results...

What actually happened?

Details

When I attached and set a breakpoint here: https://github.com/palkan/test-prof/blob/master/lib/test_prof/event_prof/instrumentations/active_support.rb#L12

The result for (finish - start) was always 0.

When I changed the code to the following:

::ActiveSupport::Notifications.subscribe(event) do |event|
  yield (event.duration / 1000.0)
end

I started getting profiling results!

Code was based on: https://blog.bigbinary.com/2019/04/24/rails-6-adds-cpu-time-idle-time-and-allocations-to-activesupport-notifications-event.html

[palkan]

Do you use something like Timecop to freeze the time?

As I see, the old style subscribers (with |_event, start, finish, *| args) use Time.now, while the new one, Evented, uses Concurrent.monotonic_time.

As I see, the difference is intentional: rails/rails@b9a9131

I think, using monotonic_subscribe instead of subscribe should fix this in Rails 6. Though for earlier versions we need a different way of dealing with patched Time.now.

[philipbjorge]

We do use Timecop -- I was wondering if something like this might have been at the root of things but am just discovering this codebase.

Can I help assist further?

[palkan]

Can I help assist further?

Thanks but I've already started working on a fix)

[palkan]

@philipbjorge Fixed in master. Will be released soon (after we finish #178).

[philipbjorge]

@palkan -- Really appreciate it!

This library just helped us shave 30-45% off of our system spec suite runtimes with potential downstream savings for other projects.

https://github.com/dequelabs/axe-matchers/issues/94