Call stacks in output are noisy

technicalpickles commented 1 year ago

We're using prosopite, but have found that the stack traces are too long and verbose to actually be useful to help find the place making the query. There's two parts to this:

it includes the full path to application code, instead of relative to Rails.root (shown in README.md)
it includes all sorts of gems that are in the call stack, but most notable it includes activesupport and activerecord at the top before the code that is actually making the N+1

Here's an example:

N+1 queries detected:
  <redacted>
Call stack:
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:236:in `finish'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:76:in `block in finish'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:91:in `block in iterate_guarding_exceptions'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:90:in `each'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:90:in `iterate_guarding_exceptions'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/fanout.rb:76:in `finish'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/instrumenter.rb:49:in `finish_with_state'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activesupport-7.0.4/lib/active_support/notifications/instrumenter.rb:30:in `instrument'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract_adapter.rb:756:in `log'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:630:in `raw_execute'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/mysql/database_statements.rb:96:in `raw_execute'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/mysql/database_statements.rb:47:in `execute'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:207:in `execute_and_free'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/mysql/database_statements.rb:52:in `exec_query'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:560:in `select'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/database_statements.rb:66:in `select_all'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/query_cache.rb:110:in `select_all'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/querying.rb:54:in `_query_by_sql'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:942:in `block in exec_main_query'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:928:in `exec_main_query'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:914:in `block in exec_queries'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:908:in `exec_queries'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/association_relation.rb:44:in `exec_queries'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:695:in `load'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation.rb:250:in `records'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation/delegation.rb:88:in `each'
  /Users/kplawver/workspace/ourapp/redacted/lib/foo.rb:29:in `block (2 levels) in blockers'
  /Users/kplawver/workspace/outapp/redacted/lib/foo.rb:24:in `each'
  /Users/kplawver/workspace/outapp/redacted/lib/foo.rb:24:in `block in blockers'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation/delegation.rb:88:in `each'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/activerecord-7.0.4/lib/active_record/relation/delegation.rb:88:in `each'
  /Users/kplawver/workspace/ourapp/redacted/lib/foo.rb:21:in `blockers'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sorbet-runtime-0.5.10572/lib/types/private/methods/call_validation.rb:256:in `bind_call'
  /Users/kplawver/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/sorbet-runtime-0.5.10572/lib/types/private/methods/call_validation.rb:256:in `validate_call'

There's only 4 lines that actually help find and resolve this (the ones in ourapp), and the rest our noise.

ActiveSupport actually has something just for this kind of thing: ActiveSupport::BacktraceCleaner. Rails sets one up accessible at Rails.backtrace_cleaner that can be tuned in an initializer (config/initializers/backtrace_silencers.rb is generated by default).

I'd like to look at using that in prosopite, but wanted to write the idea up first. I think we can just re-use the existing Rails.backtrace_cleaner, but there may also be value in having its own, or being able to tweak it separate from Rails.

cc @kplawver who was asking about this, and who had the stack trace

charkost commented 1 year ago

Sure the first sounds really good and a PR would be welcome!

For the second we already have this code: https://github.com/charkost/prosopite/blob/1f53947c5aaaca4e0dd773a91a0b8591fc449cc3/lib/prosopite.rb#L199

We should find why it doesn't work in your case.

technicalpickles commented 1 year ago

Sure the first sounds really good and a PR would be welcome!

🎉 https://github.com/charkost/prosopite/pull/54 🎉

We should find why it doesn't work in your case.

I'm not sure why it didn't, but I couldn't reproduce. I even checked if some of those filenames included Bundle.bundle_path.to_s and it did.

Separate from that not working, the backtrace cleaner offers additional benefits from checking Bundler.bundled_path that I mention on the PR:

The default Rails.backtrace_cleaner includes that plus stdlib stuff, and also cleans up files relative to the current directory (ie /Users/technicalpickles/my_app/lib/foo.rb becomes lib/foo.rb). A user can also other filters, which we've done for things like middleware that is included everywhere.

technicalpickles commented 1 year ago

Implemented and released! https://github.com/charkost/prosopite/pull/54 and https://github.com/charkost/prosopite/releases/tag/1.3.0

charkost / prosopite

Call stacks in output are noisy #53