Closed as not planned
Closed as not planned
Description
Thank you for your contribution!
Due to limited volunteers, issues that do not follow these instructions will be
closed without comment.
Check the following boxes:
- This is not a usage question, this is a bug report
- This bug can be reproduced with the script I provide below
- This bug can be reproduced in the latest release of the
paper_trailgem
Due to limited volunteers, we cannot answer usage questions. Please ask such
questions on StackOverflow.
Bug reports must use the following template:
# frozen_string_literal: true
require "bundler/inline"
gemfile(true) do
ruby "3.4.2"
source "https://rubygems.org"
gem "activerecord", "8.0.2"
gem "minitest", "5.25.5"
gem "sqlite3", "2.6.0"
# The N+1 queries bug occurs in the latest released version of paper_trail (16.0.0):
gem "paper_trail", "16.0.0"
# The bug is fixed in the following branch on my fork.
# gem 'paper_trail',
# github: 'davidrunger/paper_trail',
# branch: 'avoid-n+1-queries-in-version_limit-when-destroying'
end
ActiveRecord::Base.establish_connection(adapter: "sqlite3", database: ":memory:")
ActiveRecord::Base.logger = nil
ActiveRecord::Schema.define do
create_table :customers, force: true do |t|
t.text :name, null: false
end
create_table :orders, force: true do |t|
t.bigint :customer_id, null: false
t.string :order_date
end
create_table :versions do |t|
t.string :item_type, null: false
t.integer :item_id, null: false
t.string :event, null: false
t.string :whodunnit
t.json :object
t.json :object_changes
t.datetime :created_at, null: false
t.index %i[item_type item_id]
end
end
stdout_logger = Logger.new($stdout)
$active_record_logs = StringIO.new
stringio_logger = Logger.new($active_record_logs)
ActiveRecord::Base.logger = ActiveSupport::BroadcastLogger.new(stdout_logger, stringio_logger)
ActiveRecord::Base.logger.formatter = ActiveSupport::Logger::SimpleFormatter.new
class Customer < ActiveRecord::Base
has_many :orders, dependent: :destroy
end
class Order < ActiveRecord::Base
has_paper_trail
end
require "minitest/autorun"
class BugTest < ActiveSupport::TestCase
def test_no_n_plus_1_query_when_destroying_customer
customer = Customer.create!(name: "Customer")
customer.orders.create!
customer.orders.create!
customer.destroy!
# NOTE: Explicitly eager-loading the orders (as below) ideally shouldn't be
# needed, but, anyway, doing so still doesn't avoid the N+1 query.
# Customer.includes(:orders).find(customer.id).destroy!
# The assertion below counts SELECT queries for individual orders by id.
# There should not be any such queries. (There should only be one query for
# orders that loads together all of the orders of the customer that is being
# destroyed.) However, with `paper_trail` 16.0.0, this spec will fail, as
# there _will_ be individual queries by id for each of the orders being
# destroyed (two total, in this example). These queries are N+1 queries,
# they are not necessary, and they should not be performed.
assert_equal(
0,
$active_record_logs.string.scan(
'SELECT "orders".* FROM "orders" WHERE "orders"."id" = ?'
).size
)
end
end$ ruby n_plus_1_queries.rb
Fetching gem metadata from https://rubygems.org/...........
Resolving dependencies...
-- create_table(:customers, {force: true})
-> 0.0229s
-- create_table(:orders, {force: true})
-> 0.0011s
-- create_table(:versions)
-> 0.0054s
Run options: --seed 18890
# Running:
TRANSACTION (0.1ms) BEGIN immediate TRANSACTION
Customer Create (0.6ms) INSERT INTO "customers" ("name") VALUES (?) RETURNING "id" [["name", "Customer"]]
TRANSACTION (0.0ms) COMMIT TRANSACTION
TRANSACTION (0.1ms) BEGIN immediate TRANSACTION
Order Create (0.5ms) INSERT INTO "orders" ("customer_id") VALUES (?) RETURNING "id" [["customer_id", 1]]
PaperTrail::Version Create (0.2ms) INSERT INTO "versions" ("item_type", "item_id", "event", "object_changes", "created_at") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["item_type", "Order"], ["item_id", 1], ["event", "create"], ["object_changes", "{\"id\":[null,1],\"customer_id\":[null,1]}"], ["created_at", "2025-03-18 05:24:47.887680"]]
TRANSACTION (0.1ms) COMMIT TRANSACTION
TRANSACTION (0.1ms) BEGIN immediate TRANSACTION
Order Create (0.7ms) INSERT INTO "orders" ("customer_id") VALUES (?) RETURNING "id" [["customer_id", 1]]
PaperTrail::Version Create (0.3ms) INSERT INTO "versions" ("item_type", "item_id", "event", "object_changes", "created_at") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["item_type", "Order"], ["item_id", 2], ["event", "create"], ["object_changes", "{\"id\":[null,2],\"customer_id\":[null,1]}"], ["created_at", "2025-03-18 05:24:47.893108"]]
TRANSACTION (0.1ms) COMMIT TRANSACTION
TRANSACTION (0.0ms) BEGIN immediate TRANSACTION
Order Load (0.3ms) SELECT "orders".* FROM "orders" WHERE "orders"."customer_id" = ? [["customer_id", 1]]
PaperTrail::Version Create (0.2ms) INSERT INTO "versions" ("item_type", "item_id", "event", "object", "object_changes", "created_at") VALUES (?, ?, ?, ?, ?, ?) RETURNING "id" [["item_type", "Order"], ["item_id", 1], ["event", "destroy"], ["object", "{\"id\":1,\"customer_id\":1,\"order_date\":null}"], ["object_changes", "{\"id\":[1,null],\"customer_id\":[1,null],\"order_date\":[null,null]}"], ["created_at", "2025-03-18 05:24:47.897182"]]
Order Load (0.2ms) SELECT "orders".* FROM "orders" WHERE "orders"."id" = ? LIMIT ? [["id", 1], ["LIMIT", 1]]
Order Destroy (0.1ms) DELETE FROM "orders" WHERE "orders"."id" = ? [["id", 1]]
PaperTrail::Version Create (0.1ms) INSERT INTO "versions" ("item_type", "item_id", "event", "object", "object_changes", "created_at") VALUES (?, ?, ?, ?, ?, ?) RETURNING "id" [["item_type", "Order"], ["item_id", 2], ["event", "destroy"], ["object", "{\"id\":2,\"customer_id\":1,\"order_date\":null}"], ["object_changes", "{\"id\":[2,null],\"customer_id\":[1,null],\"order_date\":[null,null]}"], ["created_at", "2025-03-18 05:24:47.901533"]]
Order Load (0.1ms) SELECT "orders".* FROM "orders" WHERE "orders"."id" = ? LIMIT ? [["id", 2], ["LIMIT", 1]]
Order Destroy (0.1ms) DELETE FROM "orders" WHERE "orders"."id" = ? [["id", 2]]
Customer Destroy (0.1ms) DELETE FROM "customers" WHERE "customers"."id" = ? [["id", 1]]
TRANSACTION (0.0ms) COMMIT TRANSACTION
F
Finished in 0.062776s, 15.9295 runs/s, 15.9295 assertions/s.
1) Failure:
BugTest#test_no_n_plus_1_query_when_destroying_customer [n_plus_1_queries.rb:77]:
Expected: 0
Actual: 2
1 runs, 1 assertions, 1 failures, 0 errors, 0 skips
Two of the queries seen in the test output above and highlighted in the screenshot below are unnecessary N+1 queries:
Those N+1 queries for Order records (just after creating a PaperTrail::Version and just before actually destroying the Order record) occur because of the reference to item here in the PaperTrail::VersionConcern#version_limit method:
I believe that this N+1 query was probably introduced here: https://github.com/paper-trail-gem/paper_trail/pull/1309/files#diff-ce609ac9edbdf2df8bfe15246950dce5efa7efac84609883bb7a210bdef3ba39L386