Obvious N+1 query not detected in RSpec (when setup code is run before it)

[jessevdp]

Hey 👋

I'm attempting to set-up Bullet to run in my RSpec tests to detect N+1 queries and whatnot. I've followed the setup outlined in the README (here), and set a fairly obvious N+1 example that does trigger a Bullet notification when run in a controller.

I can't quite explain why, but Bullet seems to NOT detect N+1 queries when some other database interactions happen. To show what I mean consider the following two variations of the same RSpec test.

I've moved all the Bullet related code out of the general RSpec config and into the example. I've also moved the DB setup code out of a before hook into the example. This to show the timings off.

This does NOT trigger a Bullet warning

Note Bullet.start_request is invoked at the start of the example, before any DB interaction.

RSpec.describe User do

  specify "test bullet detects N+1 query" do
    Bullet.start_request

    user = create(:user)
    user.comments.create(content: "Comment 1")
    user.comments.create(content: "Comment 2")
    user.comments.create(content: "Comment 3")

    user2 = create(:user, name: "User 2")
    user2.comments.create(content: "User 2 Comment 1")
    user2.comments.create(content: "User 2 Comment 2")
    user2.comments.create(content: "User 2 Comment 3")

    comments = []

    described_class.all.each do |user|
      user.comments.each do |comment|
        comments << comment.content
      end
    end

    expect(comments).to eq(["Comment 1", "Comment 2", "Comment 3", "User 2 Comment 1", "User 2 Comment 2", "User 2 Comment 3"])

    Bullet.perform_out_of_channel_notifications if Bullet.notification?
    Bullet.end_request
  end

end

1 example, 0 failures

This does trigger a Bullet warning

Note Bullet.start_request is run just before the actual querying code.

RSpec.describe User do

  specify "test bullet detects N+1 query" do
    user = create(:user)
    user.comments.create(content: "Comment 1")
    user.comments.create(content: "Comment 2")
    user.comments.create(content: "Comment 3")

    user2 = create(:user, name: "User 2")
    user2.comments.create(content: "User 2 Comment 1")
    user2.comments.create(content: "User 2 Comment 2")
    user2.comments.create(content: "User 2 Comment 3")
    
    # Invoking Bullet after the DB setup code works
    Bullet.start_request

    comments = []

    described_class.all.each do |user|
      user.comments.each do |comment|
        comments << comment.content
      end
    end

    expect(comments).to eq(["Comment 1", "Comment 2", "Comment 3", "User 2 Comment 1", "User 2 Comment 2", "User 2 Comment 3"])

    Bullet.perform_out_of_channel_notifications if Bullet.notification?
    Bullet.end_request
  end

end

1) User test bullet detects N+1 query
     Failure/Error: Bullet.perform_out_of_channel_notifications if Bullet.notification?
     
     Bullet::Notification::UnoptimizedQueryError:
       user: jessevanderpluijm
        
       USE eager loading detected
         User => [:comments]
         Add to your query: .includes([:comments])

My environment

I run a fairly standard RSpec setup, the only other plugin I have setup is DatabaseCleaner, which should run entirely around the example. (To ensure this wasn't messing with things I moved all the Bullet code into the example.

Related issues

This might to be related to: #427. But I wanted to report this anyway since (1) that issue doesn't really have a fix, and (2) I have a more simplified version of the problem that does not have anything to do with RSpec hook execution order.

[jessevdp]

Here is the Bullet debug output for the example where it does NOT detect the N+1 query.

[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:1
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:1
[Bullet][Detector::CounterCache#add_impossible_object] object: User:1
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:1
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:1
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:1
[Bullet][Detector::CounterCache#add_impossible_object] object: User:1
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:1
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:2
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:1
[Bullet][Detector::CounterCache#add_impossible_object] object: User:1
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:1
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:3
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:2
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:2
[Bullet][Detector::CounterCache#add_impossible_object] object: User:2
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:2
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:4
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:2
[Bullet][Detector::CounterCache#add_impossible_object] object: User:2
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:2
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:5
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: User:2
[Bullet][Detector::CounterCache#add_impossible_object] object: User:2
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:2
[Bullet][Detector::NPlusOneQuery#add_impossible_object] object: Comment:6
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:1, User:2
[Bullet][Detector::CounterCache#add_possible_objects] objects: User:1, User:2
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::Association#add_call_object_associations] object: User:1, associations: comments
[Bullet][Detector::NPlusOneQuery#call_association] object: User:1, associations: comments
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::Association#add_call_object_associations] object: User:2, associations: comments
[Bullet][Detector::NPlusOneQuery#call_association] object: User:2, associations: comments
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:4, Comment:5, Comment:6

And for reference, here is the output of the second variation, where Bullet does detect the problem:

[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: User:1, User:2
[Bullet][Detector::CounterCache#add_possible_objects] objects: User:1, User:2
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::Association#add_call_object_associations] object: User:1, associations: comments
[Bullet][Detector::NPlusOneQuery#call_association] object: User:1, associations: comments
[Bullet][detect n + 1 query] object: User:1, associations: comments
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:1, Comment:2, Comment:3
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::Association#add_call_object_associations] object: User:2, associations: comments
[Bullet][Detector::NPlusOneQuery#call_association] object: User:2, associations: comments
[Bullet][detect n + 1 query] object: User:2, associations: comments
[Bullet][Detector::NPlusOneQuery#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
[Bullet][Detector::CounterCache#add_possible_objects] objects: Comment:4, Comment:5, Comment:6
  test bullet detects N+1 query (FAILED - 1)

Failures:

  1) User test bullet detects N+1 query
     Failure/Error: Bullet.perform_out_of_channel_notifications if Bullet.notification?
     
     Bullet::Notification::UnoptimizedQueryError:
       user: jessevanderpluijm
        
       USE eager loading detected
         User => [:comments]
         Add to your query: .includes([:comments])