charkost / prosopite Goto Github PK

View Code? Open in Web Editor NEW

1.5K 1.5K 45.0 76 KB

:mag: Rails N+1 queries auto-detection with zero false positives / false negatives

License: Apache License 2.0

Ruby 100.00%

performance rails

prosopite's People

Contributors

Stargazers

Watchers

prosopite's Issues

False(?) positive with uniqueness validation

We have a model with a series of unique: true validations. Prosopite is detecting the uniqueness checks as N+1s, because they are executed one after another as
SELECT 1 as one FROM "table" WHERE "column"= $1 AND id != $2 LIMIT $3

Can it be considered as a false positive case?

It's related to the rails default behavior connected to the associations assignment. Here my structure of models:

class CreateTables < ActiveRecord::Migration[6.1]
  def change
    create_table :model1s do |t|
      t.string :name
      t.timestamps
    end

    create_table :model3s do |t|
      t.string :name
      t.timestamps
    end

    create_table :model2s do |t|
      t.string :name
      t.belongs_to :model3, foreign_key: true, null: false, index: true

      t.timestamps
    end

    create_table :model1_model2s do |t|
      t.belongs_to :model1, foreign_key: true, null: false, index: true
      t.belongs_to :model2, foreign_key: true, null: false, index: true

      t.timestamps
    end
  end
end

Schema change:

  create_table "model1_model2s", force: :cascade do |t|
    t.bigint "model1_id", null: false
    t.bigint "model2_id", null: false
    t.datetime "created_at", precision: 6, null: false
    t.datetime "updated_at", precision: 6, null: false
    t.index ["model1_id"], name: "index_model1_model2s_on_model1_id"
    t.index ["model2_id"], name: "index_model1_model2s_on_model2_id"
  end

  create_table "model1s", force: :cascade do |t|
    t.string "name"
    t.datetime "created_at", precision: 6, null: false
    t.datetime "updated_at", precision: 6, null: false
  end

  create_table "model2s", force: :cascade do |t|
    t.string "name"
    t.bigint "model3_id", null: false
    t.datetime "created_at", precision: 6, null: false
    t.datetime "updated_at", precision: 6, null: false
    t.index ["model3_id"], name: "index_model2s_on_model3_id"
  end

  create_table "model3s", force: :cascade do |t|
    t.string "name"
    t.datetime "created_at", precision: 6, null: false
    t.datetime "updated_at", precision: 6, null: false
  end

Model classes:

class Model1 < ApplicationRecord
  has_many :model1_model2s, dependent: :destroy
  has_many :model2s, through: :model1_model2s
end

class Model1Model2 < ApplicationRecord
  belongs_to :model1
  belongs_to :model2
end

class Model2 < ApplicationRecord
  belongs_to :model3
end

class Model3 < ApplicationRecord
end

I've seeded some data to demonstrate:

Loading development environment (Rails 6.1.7.4)
[1] pry(main)> Model3.create(name: 'first model3')
D, [2023-06-28T15:26:04.642995 #17820] DEBUG -- :   TRANSACTION (0.2ms)  BEGIN
D, [2023-06-28T15:26:04.646155 #17820] DEBUG -- :   Model3 Create (2.9ms)  INSERT INTO "model3s" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "first model3"], ["created_at", "2023-06-28 13:26:04.639608"], ["updated_at", "2023-06-28 13:26:04.639608"]]
D, [2023-06-28T15:26:04.647695 #17820] DEBUG -- :   TRANSACTION (0.5ms)  COMMIT
=> #<Model3:0x00000001118c83b0
 id: 1,
 name: "first model3",
 created_at: Wed, 28 Jun 2023 13:26:04.639608000 UTC +00:00,
 updated_at: Wed, 28 Jun 2023 13:26:04.639608000 UTC +00:00>
[2] pry(main)> Model3.create(name: 'second model3')
D, [2023-06-28T15:26:09.963816 #17820] DEBUG -- :   TRANSACTION (0.9ms)  BEGIN
D, [2023-06-28T15:26:09.966308 #17820] DEBUG -- :   Model3 Create (1.9ms)  INSERT INTO "model3s" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "second model3"], ["created_at", "2023-06-28 13:26:09.961775"], ["updated_at", "2023-06-28 13:26:09.961775"]]
D, [2023-06-28T15:26:09.968353 #17820] DEBUG -- :   TRANSACTION (1.7ms)  COMMIT
=> #<Model3:0x0000000127ee6e48
 id: 2,
 name: "second model3",
 created_at: Wed, 28 Jun 2023 13:26:09.961775000 UTC +00:00,
 updated_at: Wed, 28 Jun 2023 13:26:09.961775000 UTC +00:00>
[3] pry(main)> Model2.create(name: 'first model2', model3_id: 1)
D, [2023-06-28T15:26:43.233983 #17820] DEBUG -- :   TRANSACTION (0.2ms)  BEGIN
D, [2023-06-28T15:26:43.235785 #17820] DEBUG -- :   Model3 Load (0.9ms)  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
D, [2023-06-28T15:26:43.248777 #17820] DEBUG -- :   Model2 Create (5.3ms)  INSERT INTO "model2s" ("name", "model3_id", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["name", "first model2"], ["model3_id", 1], ["created_at", "2023-06-28 13:26:43.240450"], ["updated_at", "2023-06-28 13:26:43.240450"]]
D, [2023-06-28T15:26:43.249256 #17820] DEBUG -- :   TRANSACTION (0.3ms)  COMMIT
=> #<Model2:0x000000011206e5b0
 id: 1,
 name: "first model2",
 model3_id: 1,
 created_at: Wed, 28 Jun 2023 13:26:43.240450000 UTC +00:00,
 updated_at: Wed, 28 Jun 2023 13:26:43.240450000 UTC +00:00>
[4] pry(main)> Model2.create(name: 'second model2', model3_id: 2)
D, [2023-06-28T15:26:53.230830 #17820] DEBUG -- :   TRANSACTION (1.0ms)  BEGIN
D, [2023-06-28T15:26:53.231945 #17820] DEBUG -- :   Model3 Load (0.8ms)  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2  [["id", 2], ["LIMIT", 1]]
D, [2023-06-28T15:26:53.243935 #17820] DEBUG -- :   Model2 Create (1.9ms)  INSERT INTO "model2s" ("name", "model3_id", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["name", "second model2"], ["model3_id", 2], ["created_at", "2023-06-28 13:26:53.241281"], ["updated_at", "2023-06-28 13:26:53.241281"]]
D, [2023-06-28T15:26:53.245525 #17820] DEBUG -- :   TRANSACTION (1.3ms)  COMMIT
=> #<Model2:0x0000000110947f80
 id: 2,
 name: "second model2",
 model3_id: 2,
 created_at: Wed, 28 Jun 2023 13:26:53.241281000 UTC +00:00,
 updated_at: Wed, 28 Jun 2023 13:26:53.241281000 UTC +00:00>

And then I try to create a first record into model1s table under Prosopite scanning:

Loading development environment (Rails 6.1.7.4)
[1] pry(main)> Prosopite.scan do
[1] pry(main)*   Model1.create(name: 'first model 1', model2_ids: [1, 2])
[1] pry(main)* end  
D, [2023-06-28T15:28:24.628757 #18165] DEBUG -- :   Model2 Load (1.4ms)  SELECT "model2s".* FROM "model2s" WHERE "model2s"."id" IN ($1, $2)  [["id", 1], ["id", 2]]
D, [2023-06-28T15:28:24.643451 #18165] DEBUG -- :   TRANSACTION (0.4ms)  BEGIN
D, [2023-06-28T15:28:24.653446 #18165] DEBUG -- :   Model3 Load (1.2ms)  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
D, [2023-06-28T15:28:24.655743 #18165] DEBUG -- :   Model3 Load (0.2ms)  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2  [["id", 2], ["LIMIT", 1]]
D, [2023-06-28T15:28:24.661395 #18165] DEBUG -- :   Model1 Create (4.4ms)  INSERT INTO "model1s" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "first model 1"], ["created_at", "2023-06-28 13:28:24.656399"], ["updated_at", "2023-06-28 13:28:24.656399"]]
D, [2023-06-28T15:28:24.665641 #18165] DEBUG -- :   Model1Model2 Create (3.6ms)  INSERT INTO "model1_model2s" ("model1_id", "model2_id", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["model1_id", 1], ["model2_id", 1], ["created_at", "2023-06-28 13:28:24.661745"], ["updated_at", "2023-06-28 13:28:24.661745"]]
D, [2023-06-28T15:28:24.666998 #18165] DEBUG -- :   Model1Model2 Create (0.7ms)  INSERT INTO "model1_model2s" ("model1_id", "model2_id", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["model1_id", 1], ["model2_id", 2], ["created_at", "2023-06-28 13:28:24.666014"], ["updated_at", "2023-06-28 13:28:24.666014"]]
D, [2023-06-28T15:28:24.667778 #18165] DEBUG -- :   TRANSACTION (0.4ms)  COMMIT
Prosopite::NPlusOneQueriesError: N+1 queries detected:
  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2
  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2
Call stack:
  (pry):2:in `block in <main>'
  (pry):1:in `<main>'


from /Users/snookerovich/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/prosopite-1.3.2/lib/prosopite.rb:229:in `send_notifications'

I guess it looks like a false positive attempt. Is there a way to mute Prosopite when running rails default methods like save, create, or update? Is solution below the only way?

Prosopite.scan
...
Prosopite.pause { Model1.create(name: 'first model 1', model2_ids: [1, 2]) }
...
Prosopite.finish

false positives in multithreaded envs?

Not sure, seem that because of storing state in

    def tc
      Thread.current
    end

for each thread the ActiveSupport::Notifications.subscribe 'sql.active_record' is run, creating a new subscriber, and causing false positives because each message is duplicated by the number of Puma threads.

FEATURE: Make output more configurable

Feature: I want to be able to report a summary of the found issues.

For example, here's my code I've hacked right now. Ideally I could do this via some post-processor callback prior to logger.warn which let's be post-process the generated message.

class TestLogger < ActiveSupport::Logger
  def initialize
    @file = StringIO.new
    super(@file)
  end

  def messages
    @file.rewind
    @file.read
  end
end

and in the test env

  require Rails.root.join("lib", "test_logger")
  prosopite_logger = Class.new(TestLogger) do
    # Shrink down size of notification.
    def warn(progname, &block)
      progname = extract_interesting_lines(progname)
      super
    end

    def extract_interesting_lines(progname)
      lines = progname.split("\n")
      interesting_traces = {}
      lines.each_with_index do |call_stack_line, index|
        next unless /Call stack/i.match?(call_stack_line)
        interesting_lines = lines[index - 1..index + 1]
        interesting_lines.each do |interesting_line|
          interesting_line.gsub!(/#{Rails.root.to_path}\//, "")
        end
        interesting_traces[interesting_lines.last] = interesting_lines.join("\n")
      end
      interesting_traces
        .to_a
        .sort_by(&:first)
        .map(&:last)
        .join("\n\n")
    end
    # def add(severity, message = nil, progname = nil, &block) # :nodoc:
    # end
  end.new
  Rails.application.configure do
    config.after_initialize do
      Prosopite.custom_logger = prosopite_logger
      # TODO(BF): When all the warnings are gone
      # Prosopite.rails_logger = true
      # Prosopite.raise = true
    end
  end
  RSpec.configure do |config|
    config.before(:each) do
      Prosopite.scan
    end

    config.after(:each) do
      Prosopite.finish
    end

    config.after(:suite) do
      messages = prosopite_logger.messages
      next if messages.blank?
      message = <<~EOS
        ---------------- N+1 WARNINGS -------------------
        #{messages}
        ---------------------------------------------
      EOS
      if ENV["LOG"]
        ::Rails.logger.info message
      else
        $stderr.puts message # rubocop:disable Style/StderrPuts
        if !ENV["CI"]
          File.write(Rails.root.join("log", "prosopite_test.log"), message)
        end
      end
    end
  end

Refactor responsibilities out from single class

Right now, the Prosopite does quite a bit. I think it could be helpful to refactor out some of the logic into their own classes to better encapsulate the behavior. The main areas I can identify so far are:

configuration
notifying
fingerprinting
scanning (scan, start, stop, subscribing to activerecord events)

I kinda started a branch for this already, but I figured I'd gauge interest appetite before dropping a big PR 😅

Ability to disable using comments

It wold be good to be able to disable Prosopite for certain code blocks but keep it on for the whole test suite. Similar to how Rubocop does it. So something like:

prosopite:disable NPlusOneQueriesError
[some code that generates N+1 queries]
prosopite:enable NPlusOneQueriesError

N+1 error for `upsert_all` with `unique_by` in Rails with postgres

Thanks for your great gem! I have just discovered it and so far it looks like a great alternative to bullet.
This one behaviour is slightly annoying though because my main motivation for using one of rails' upsert_alls is to reduce the number of queries. I think the main problematic part is the unique_by keyword, which triggers some internal lookups which are beyond your control:

       -- N+1 queries detected:
         SELECT a.attnum, a.attname
       FROM pg_attribute a
       WHERE a.attrelid = 119170
       AND a.attnum IN (3)
     
         SELECT a.attnum, a.attname
       FROM pg_attribute a
       WHERE a.attrelid = 119170
       AND a.attnum IN (3,2)
     
         SELECT a.attnum, a.attname
       FROM pg_attribute a
       WHERE a.attrelid = 119170
       AND a.attnum IN (2)

And if I run these queries by themselves I get back the attributes which I passed into the unique_by.

Example (haven't tested this precise code below, but it's more or less a simplified version of what I have):

# table
create_table :posts do |t|
  t.string :author_name
  t.string :title
  t.text :description
  t.index %i[author_name title], unique: true
end

# model
class Post < ActiveRecord::Base
  validates_uniqueness_of :title, scope: :author_name
end

# action
Post.upsert_all(
  [
    { author_name: "Geoff", title: "Foo", description: "bar" },
    { author_name: "Frank", title: "Baz", description: "hello world" },
    # etc...
  ],
  unique_by: %i[author_name title]
)

Would it be possible to exclude any queries to the pg_* tables for postgres users? Or maybe allow users to specify a whitelist for specific tables?

My current workaround is to find the specific line within active_record and add it to the allow_list - but this feels sub-optimal, as obviously this could very easily change:

Prosopite.allow_list = ["active_record/persistence.rb:243"]

How does this gem differs from Rails strict_loading?

Thanks for the great work on this gem.
Can we compare more in depth why would this gem be useful given that Rails strict_loading exists? (and maybe we can add it to the Readme)

For me, I understand that strict_loading prevents all kinds of lazy loading, which includes n+1 issues but also includes other things, it is very hard for me to pinpoint how those 2 cases diverge

In other words: what are lazy loading cases that will throw exception in strict_loading but are NOT N+1 issues?
Plus, any other points you think are handled better in Prosopite

Thanks

False positive when used together with FactoryBot `create_list`?

Hi, seems like there is a false positive when used together with FactoryBot create_list. I'm not sure if the problem is in Prosopite codebase or somewhere else, but I'd like to hear others' thoughts.

I created a reproduction script:

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # Activate the gem you are reporting the issue against.
  gem "rails", "~> 7.0.0"
  gem "sqlite3", "~> 1.6.4"
  gem "prosopite", "~> 1.3.3"
  gem "pg_query", "~> 4.2.3"
  gem "factory_bot_rails", "~> 6.2.0"
end

require "active_record/railtie"
require "active_storage/engine"
require "tmpdir"
require "minitest/autorun"

class TestApp < Rails::Application
  config.root = __dir__
  config.hosts << "example.org"
  config.eager_load = false
  config.session_store :cookie_store, key: "cookie_store_key"
  config.secret_key_base = "secret_key_base"

  config.logger = Logger.new($stdout)
  Rails.logger  = config.logger

  config.active_storage.service = :local
  config.active_storage.service_configurations = {
    local: {
      root: Dir.tmpdir,
      service: "Disk"
    }
  }
end

ENV["DATABASE_URL"] = "sqlite3::memory:"

Rails.application.config.after_initialize do
  Prosopite.rails_logger = true
  Prosopite.raise = true
end

Rails.application.initialize!

require ActiveStorage::Engine.root.join("db/migrate/20170806125915_create_active_storage_tables.rb").to_s

ActiveRecord::Schema.define do
  CreateActiveStorageTables.new.change

  create_table :users, force: true
end

class User < ActiveRecord::Base
  has_one_attached :profile
end

FactoryBot.define do
  factory :user do
    profile { { content_type: "text/plain", filename: "dummy.txt", io: ::StringIO.new("dummy") } }
  end
end

class BugTest < Minitest::Test
  def setup
    Prosopite.scan
  end

  def teardown
    Prosopite.finish
  end

  def test_it_works
    FactoryBot.create(:user)
    FactoryBot.create(:user)
  end

  def test_it_doesnt_work
    FactoryBot.create_list(:user, 2)
  end
end

as you can see, two create works fine, but one create_list(.., 2) doesn't

What if we separate detection and reporting?

May I suggest adding silent N+1 detection to the public API?

I don't feel a need to log or raise on N+1, but instead I'd rather have a report and build my own notifications based on it.

Example:

  Prosopite.scan do
    NPlusOne.perform
  end # => return report in form of queries, caller and count

  Prosopite.scan! do
    NPlusOne.perform
  end # => run reporting via logging or raising or both.

Implement a replacement for the `add_footer` option of bullet

It would be really awesome if we could imitate the add_footer option of bullet.

I understand that getting involved with the view side of things may not be a core concern.

If native support is not possible, I would love for the project to include a simple example implementation of how to add this to a project.

pg_query dependency

It should be possible to require pg_query on demand and remove runtime dependency for MySQL apps.

Fix license

Can you fill in your data in license ?
https://github.com/charkost/prosopite/blob/main/LICENSE.txt#L190

Changelog is missing, but I know that it is early stage of project : )

Call stacks in output are noisy

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

False negative when using ActiveRecord::Associations::Preloader

I found that in the source code if that Prosopite will automatic allow caller with ActiveRecord::Associations::Preloader

DEFAULT_ALLOW_LIST = %w(active_record/associations/preloader active_record/validations/uniqueness)

This could lead in false positive if a user manually uses ActiveRecord::Associations::Preloader to eager loading association.

Adding Sidekiq middleware

I'm having an issue setting up prosopite with sidekiq.

I added the same snippet in the docs but getting uninitialized constant Sidekiq::ServerMiddleware.

I'm using Sidekiq 4.2.10
I tried checking if Prosopite needs a certain version for that but no luck. Any help?

Chrome console logger option

Coming from bullet gem, would be really cool to see chrome console logger as option for outputting results. As developers live in the developer tools will makes it more visible for them.

Not ready to work with multiple databases

As I can see in source prosopite uses ActiveRecord::Base to define database adapter. If you have multiple databases you probably have multiple successors of ApplicationRecord where each of them uses different database. When prosopite uses ActiveRecord::Base it will always get adapter of primary database which is not correct. As a result, gem just fails when encounters active record queries from not primary database and can't be used at all.

Not sure if it's easy fix, but maybe it is worth mentioning it in docs?

N+1 Errors raised in RSpec test without associations

I have a controller that loads two records of the same model, does some work on both of them, then returns an OK. The test for this is failing because Prosopite thinks that the two load queries are an N+1, when in fact they're just the same query being run twice.

I don't see a simple way to prevent this.

False positives for associations involving the same table

There is a case of false positive N+1 warnings for a model with two associations pointing to the same table e.g.:

class AccountTransfer
  belongs_to :source, class_name: 'Account'
  belongs_to :target, class_name: 'Account'
end

Even if we include both associations to a fetching query, we get a warning for N+1s. I suspect that it fails to recognise that the extra query is part of the preloading.

Allow setting a custom logger?

Hi! I was trying out Prosopite in one of our project and looks really good so far :) congrats!

We don't use the raise option as it would be too disruptive (sadly we have a few old n+1 that will take some time to fix that we don't have) so, I thought that it would be nice to log the errors in RED so no one can say they didn't see them 🤣

What do you think about adding that option to the config or perhaps, simplify the config to a single logger entry?

I'm currently using this patch which implements the second option: F-3r@4db811c

I can open a PR if you think it is worth it.

PS: Also, now that I've been looking into the code, I was wondering if you would be interested in some peer-code-review?

Add Changelog

Please add a changelog so we can see whats changed between versions.

Would you be ok with making `Prosopite.pause`, `Prosopite.scan`, and `Prosopite.resume` handle nesting?

Hi @charkost

I've a situation where my specs do something like this:

let(:x) { create(:something) }
it "does that thing" do
  SomeService.new(something).call
end

The create(:something) uses FactoryBot to build a whole series of nested objects and relationships. I've wrapped specs in Prosopite.scan blocks as per https://github.com/charkost/prosopite

In my factories, some parts of the build code perform N+1 queries, and the let clause is triggering them. Since I'm trying to find N+1s in SomeService (not in my FactoryBot Factories) I'd like to ignore them. First question: Do you know of some way to avoid that?

The second problem that I'm encountering is that it doesn't seem that the pause/resume functionality is built with nesting in mind. If I pause at the top level, and then pause/resume in a 'lower' level, the second resume will un-pause the first pause. So if I Prosopite.pause inside a factorybot builder, and that builder uses another factorybot builder that also uses Prosopite.pause/Prosopite.resume, the second Prosopite.resume un-pauses the first one.

Here's a test that shows the behaviour.

  def test_pause_reentrant
    # 20 chairs, 4 legs each
    chairs = create_list(:chair, 20)
    chairs.each { |c| create_list(:leg, 4, chair: c) }

    Prosopite.scan
    # Immediately pause
    Prosopite.pause

    Chair.last(20).each do |c|
      Prosopite.pause
      c.legs.last
      Prosopite.resume
    end

    # This shouldn't trigger N+1s because we paused before the each loop above
    Chair.last(20).each do |c|
      c.legs.last
    end
    Prosopite.resume

    assert_no_n_plus_ones
  end

One way to avoid this would be to change pause and resume to increment a counter, and only resume fully on when the most-outmost resume is set. That'd mean undoing 98bcb2b though. I think there are other ways to deal with that problem though (someone calling resume when scan hadn't been called.

Add the ability to scan using a block

Prosopite.scan do
end

New release to include pause/resume

Hi,

Is it possible to publish a new release to include the changes in cba0026?

Thanks!

Why after_initialize?

Hello, the doc says to wrap the configurations in the initializer inside a Rails.application.config.after_initialize... was wondering why that is?

Handling Bulk `find_or_create` Operations?

We use a pattern like this often in our codebase:

user_attributes.each do |user_attrs|
  user = User.find_or_create_by!(email: user_attrs[:email], account: user_attrs[:account]) do |u|
    u.name = user_attrs[:name]
  end
end

This triggers a Prosopite error because of the sequential SELECTs. What's a good way to have bulk operations like this ignored by Prosopite?

Not working with Rails 6.0.3.4 in Docker environment?

I wanted to try this gem and replace bullet. But so far I could not finish setup and get it working.

I use Docker, and my Rails environment is:

Docker ruby:2.7.3-slim-buster
rails 6.0.3.4
ruby 2.7.3p183

# Gemfile
gem "puma", "~> 5.0"
gem "pg", "~> 1.2"

group :development, :test do
  gem "prosopite", "~> 1.0", ">= 1.0.1"
  gem "pg_query", "~> 2.0", ">= 2.0.3"
end

I use setup from readme:

# config/environments/development.rb
Rails.application.configure do
  ...
  config.after_initialize do
    Prosopite.rails_logger = true
    Prosopite.prosopite_logger = true
  end
end

# app/controllers/application_controller.rb
...
unless Rails.env.production?
  before_action do
    Prosopite.scan
  end

  after_action do
    Prosopite.finish
  end
end
...

But, no prosopite logging is showing up. Neither in rails nor in prosopite logs.

Do I need some libs, to run it in Docker?
Did I miss some setup for PG?

Scan without grouping by call stack

Would be probably useful to have a mode to disable grouping by call stack. Currently

record.reload; 
record.reload;

does not trigger a warning, but

current_user.reload; current_user.reload;

does, I assume because they have the same call stack line. This may be useful for cases when I just know that all data can be memorized (no updates and no long polling).

Ignore specific files

Hi! Is it possible somehow to ignore specific files, such as FactoryBot's factories? Thanks :)

Accusation for many false positives

Prosopite is defined as "Rails N+1 queries auto-detection with zero false positives / false negatives".
However, In this week's rubyweekly issue @pawurb the author of "How to Find, Debug and Fix N+1 Queries in Rails" accuses prosopite for "many false positives":

bullet and prosopite gems are popular tools for reporting N+1 issues. However, their log outputs are a bit noisy or even illegible for larger projects. I’ve also seen them report many false positives so extracting actionable data from these gems could be challenging.

@pawurb could you provide some evidence for your claims here?

We are currently not aware of any such case & we have zero unresolved GH issues for false positives as anyone can see.

Block syntax for scanning, finishing, pausing and resuming.

What do you think about supporting a block style syntax for enabling/disabling N+1 detection.

For example:

Prosopite.scan do
  example.run
end

in addition to:

Prosopite.scan
example.run
Prosopite.finish

Similarly, pausing could be something like:

Prosopite.pause do
  code_with_n+1()
end

in addition to:

Prosopite.pause
  code_with_n+1()
Prosopite.resume

The presence of N+1 queries while using Turbo causes response times to consistently increase

The problem is that response times consistently and gradually increase when there is an N+1 query and prosopite is enabled and Turbo is being used. The simplest way to reproduce the issue seems to be paginating over a large set of data that includes a count of related records.

I created this repository to help easily see the issue - the readme outlines how to set it up and reproduce it:
https://github.com/JamesChevalier/turbo_response_slowdown
I tried to make the commits in a way that also helped give a view of only the relevant parts. This commit is the most relevant view of the issue.

Versions of relevant pieces:

Ruby 3.0.2
Rails 6.1.4.1
prosopite 1.0.3
turbo-rails 7.1.0
@hotwired/turbo 7.0.1

I suppose the fix is to not have N+1 queries. 😅 😆

Please the output character encoding to be UTF-8.

prosopite/lib/prosopite.rb

Lines 161 to 163 in 4dc489c

 File.open(File.join(Rails.root, 'log', 'prosopite.log'), 'a') do |f| 

 f.puts(notifications_str) 

 end

The character encoding of notifications_str here is ASCII-8BIT, so it fails to be converted to UTF-8 when writing the file.
Can you please change the output character encoding to UTF-8?

Deprecation / error on next Rails

This line: https://github.com/charkost/prosopite/blob/36f7f5a4fa800fcfa1f9bef5cae94c9739b128fc/lib/prosopite.rb#L147C20-L147C71

Is hitting this: https://github.com/rails/rails/blob/a6a840f150d2d153af33648d93fc4553f5a3857e/activerecord/lib/active_record/connection_handling.rb#L263-L276

See rails/rails#51349

btw. it's hard to debug because it just raises the query rather than the error, here:

prosopite/lib/prosopite.rb

Line 125 in 36f7f5a

raise q

ruby 2.3 support ?

Is this an option ? Would love to provide a PR.

Eager loading expression failing

I'm getting an error below for the following eager-loading snippet

  def set_transcript
    @transcript ||= Transcript
      .includes(:institution, :transcript_awards, transcript_courses: :course)
      .find(params[:id]) # line 91
  end

I thought this was "good rails" with all its eager loading. Thoughts on how this should be rewritten?

TranscriptsControllerTest::as institution account#test_0001_should get edit:
Prosopite::NPlusOneQueriesError: N+1 queries detected:
  SELECT "institutions".* FROM "institutions" WHERE "institutions"."id" = $1
  SELECT "transcript_awards".* FROM "transcript_awards" WHERE "transcript_awards"."transcript_id" = $1
Call stack:
  /Users/drnic/workspace/prior-study-credit/prior-study-credit/app/controllers/transcripts_controller.rb:91:in `set_transcript'

Failing for a fixture finder

I added prosopite, turned on test exceptions, and watched 43 of my tests explode. Cool. Except when I look at the errors, I'm struggling to figure out what is the issue.

One error complains about a rails fixture finder method:

WorkflowAssignableControllerTest#test_0001_searches for people:
Prosopite::NPlusOneQueriesError: N+1 queries detected:
  SELECT "institutions".* FROM "institutions" WHERE "institutions"."id" = $1 LIMIT $2
  SELECT "institutions".* FROM "institutions" WHERE "institutions"."id" = $1 LIMIT $2
  SELECT "institutions".* FROM "institutions" WHERE "institutions"."id" = $1 LIMIT $2
  SELECT "institutions".* FROM "institutions" WHERE "institutions"."id" = $1 LIMIT $2
Call stack:
  /Users/drnic/workspace/prior-study-credit/prior-study-credit/test/models/institution_test.rb:33:in `block in <class:InstitutionTest>'

institution_test.rb:33 is:

class InstitutionTest < ActiveSupport::TestCase
  include ActiveJob::TestHelper

  setup do
    @institution = institutions(:uq) # 33
  end

What is the issue being raised here and what's the fix?

	File.open(File.join(Rails.root, 'log', 'prosopite.log'), 'a') do \|f\|
	f.puts(notifications_str)
	end

charkost / prosopite Goto Github PK

prosopite's People

Contributors

Stargazers

Watchers

Forkers

prosopite's Issues

Recommend Projects

Recommend Topics

Recommend Org