Can it be considered as a false positive case?

Question

Can it be considered as a false positive case?

Opened this issue a year ago · 1 comments

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

Answer 1 · 2024-03-15T20:22:35.000Z

Yes, I am in the same situation. this is a false positive. I am not going to deep dive into Instrument which is what uses this gem to detect the N+1, but it is odd it can not differentiate the arguments in

  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2
  SELECT "model3s".* FROM "model3s" WHERE "model3s"."id" = $1 LIMIT $2

Only takes into account the query without the arguments, which definitely the difference.