Instrument Reflex processing in development and log a summary

[Matt-Yorkley]

Enhancement

Description

Tracks time spent processing a Reflex and spits out a summary in the logs (in development) on completion, eg:

Processed LikeReflex#like in 28.8ms (Views: 5.4ms | ActiveRecord: 9.3ms | Allocations: 13497)

Why should this be added

It's nice to see the summaries when optimising querying / rendering.

Checklist

• [ ] My code follows the style guidelines of this project
• [ ] Checks (StandardRB & Prettier-Standard) are passing

Before (wall of text):

After (summaries and newline):

[netlify[bot]]

✅ Deploy Preview for stimulusreflex ready!

Name	Link
🔨 Latest commit	876bf7c20c9e63aaaabd68204ed44eb177dea28c
🔍 Latest deploy log	https://app.netlify.com/sites/stimulusreflex/deploys/6600385b9c9b400008434b87
😎 Deploy Preview	https://deploy-preview-686--stimulusreflex.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

---

To edit notification comments on pull requests, go to your Netlify site configuration.

[marcoroth]

Thanks for opening this @Matt-Yorkley, this is great! Would you mind resolving the Standard errors?

[marcoroth]

I just ran this in my app and encountered this error when calling a reflex, do you have a hunch what this could be about?

Reflex FolderReflex#edit failed: wrong number of arguments (given 5, expected 1) [http://localhost:3000/]
/Users/marcoroth/Development/stimulus_reflex/lib/stimulus_reflex/instrumentation.rb:11:in `block (2 levels) in track'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/fanout.rb:186:in `finish'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/fanout.rb:63:in `block in finish'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/fanout.rb:63:in `each'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/fanout.rb:63:in `finish'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/instrumenter.rb:45:in `finish_with_state'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.1.7.7/lib/active_support/notifications/instrumenter.rb:30:in `instrument'
/Users/marcoroth/.anyenv/envs/rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-6.1.7.7/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'

[Matt-Yorkley]

Yikes! First thought from eyeballing the stacktrace; is the public interface for Benchmark.realtime is different between Ruby versions? Something there is expecting a different number of arguments.

I'll take a look...

[Matt-Yorkley]

It's related to changes in ActiveSupport::Notifications between Rails versions... it works fine in 7.1.3 :disappointed:

[Matt-Yorkley]

I just tried a quick dirty-downgrade to Rails 6 to check this out and it looks like if the callback passed to ActiveSupport::Notifications.subscribed is a Lambda in Rails 6 it doesn't like it(?), but changing it to a Proc fixes the issue and also works fine in 7.0 and 7.1.

[marcoroth]

Thanks for giving this a look @Matt-Yorkley! Seems like that did the trick!

The only other thing I noticed is that the log entries can appear out-of-order. But, I'm not sure we can actually do something about this:

Do you see a way how we could resolve this? If not, we can probably merge this as-is.

[Matt-Yorkley]

Are you doing a page morph? It looks like the reflex executes, then a controller instance is handling a page render, then the broadcast is going out via ActionCable?

Might be getting a bit philosophical here, but is that order even incorrect?