prosopite
prosopite copied to clipboard
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
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.