ContextQMD
Back to Gitlabhq

QueryRecorder

doc/development/database/query_recorder.md

18.11.213.2 KB
Original Source

QueryRecorder is a tool for detecting the N+1 queries problem from tests.

Implemented in spec/support/query_recorder.rb via 9c623e3e

As a rule, merge requests should not increase query counts. If you find yourself adding something like .includes(:author, :assignee) to avoid having N+1 queries, consider using QueryRecorder to enforce this with a test. Without this, a new feature which causes an additional model to be accessed can silently reintroduce the problem.

How a QueryRecorder works

This style of test works by counting the number of SQL queries executed by ActiveRecord. First a control count is taken, then you add new records to the database and rerun the count. If the number of queries has significantly increased then an N+1 queries problem exists.

As an example you might create 5 issues in between counts, which would cause the query count to increase by 5 if an N+1 problem exists.

ruby
it "avoids N+1 database queries", :request_store, :use_sql_query_cache do
  visit_some_page # warm-up

  control = ActiveRecord::QueryRecorder.new(skip_cached: false) { visit_some_page }
  create_list(:issue, 5)
  expect { visit_some_page }.to issue_same_number_of_queries_as(control)
end

You can also have both the expectation and the control as QueryRecorder instances:

ruby
it "avoids N+1 database queries", :request_store, :use_sql_query_cache do
  visit_some_page # warm-up

  control = ActiveRecord::QueryRecorder.new(skip_cached: false) { visit_some_page }
  create_list(:issue, 5)
  action = ActiveRecord::QueryRecorder.new(skip_cached: false) { visit_some_page }

  expect(action).to issue_same_number_of_queries_as(control)
end

In some cases, the query count might change slightly between runs for unrelated reasons. In this case you might need to test issue_same_number_of_queries_as(control).with_threshold(acceptable_change), but this should be avoided if possible.

If this test fails, and the control was passed as a QueryRecorder, then the failure message indicates where the extra queries are by matching queries on the longest common prefix, grouping similar queries together.

The recommended pattern for N+1 query tests includes important components to ensure your test accurately reflects production behavior:

ruby
it "avoids N+1 database queries", :request_store, :use_sql_query_cache do
  visit_some_page # warm-up

  control = ActiveRecord::QueryRecorder.new(skip_cached: false) { visit_some_page }
  create_list(:issue, 5)
  expect { visit_some_page }.to issue_same_number_of_queries_as(control)
end

Each component serves a specific purpose:

  • :request_store: Enables Gitlab::SafeRequestStore, which caches data in memory for the duration of a request. This is enabled in production but disabled by default in tests. Without it, you may get false results.
  • :use_sql_query_cache: Enables the SQL query cache that is already active in production.
  • skip_cached: false: Counts ALL queries including cached ones. This catches N+1 queries that might be masked by caching.
  • issue_same_number_of_queries_as: Fails if the query count increases OR decreases unexpectedly (bidirectional).
  • warm-up: Handles one-time initialization queries that do not repeat on subsequent requests, such as schema loading.

Why use issue_same_number_of_queries_as over exceed_query_limit

Prefer issue_same_number_of_queries_as over exceed_query_limit because it is bidirectional; it fails if the query count increases OR decreases unexpectedly. This helps catch unintended changes in either direction, such as when a refactor accidentally removes necessary queries or when dead code is being executed.

In contrast, exceed_query_limit only fails when queries exceed the expected count, so it does not alert you if queries unexpectedly decrease.

Use request specs instead of controller specs

Use a request spec when writing a N+1 test on the controller level.

Controller specs should not be used to write N+1 tests as the controller is only initialized once per example. This could lead to false successes where subsequent "requests" could have queries reduced (for example, because of memoization).

Never trust a test you haven't seen fail

Before you add a test for N+1 queries, you should first verify that the test fails without your change. This is because the test may be broken, or the test may be passing for the wrong reasons.

To verify your test:

  1. Write the test with the recommended pattern.
  2. Temporarily remove or comment out your N+1 fix.
  3. Run the test and confirm it fails with the expected query count increase.
  4. Restore your fix and confirm the test passes.

Finding the source of the query

There are multiple ways to find the source of queries.

  • Inspect the QueryRecorder data attribute. It stores queries by file_name:line_number:method_name. Each entry is a hash with the following fields:

    • count: the number of times a query from this file_name:line_number:method_name was called
    • occurrences: the actual SQL of each call
    • backtrace: the stack trace of each call (if either of the two following options were enabled)

    QueryRecorder#find_query allows filtering queries by their file_name:line_number:method_name and count attributes. For example:

    ruby
    control = ActiveRecord::QueryRecorder.new(skip_cached: false) { visit_some_page }
control.find_query(/.*note.rb.*/, 0, first_only: true)

    QueryRecorder#occurrences_by_line_method returns a sorted array based on data, sorted by count.

  • View the call backtrace for the specific QueryRecorder instance you want by using ActiveRecord::QueryRecorder.new(query_recorder_debug: true). The output is stored in file test.log.

  • Enable the call backtrace for all tests using the QUERY_RECORDER_DEBUG environment variable.

    To enable this, run the specs with the QUERY_RECORDER_DEBUG environment variable set. For example:

    shell
    QUERY_RECORDER_DEBUG=1 bundle exec rspec spec/requests/api/projects_spec.rb

    This logs calls to QueryRecorder into the test.log file. For example:

    sql
     QueryRecorder SQL: SELECT COUNT(*) FROM "issues" WHERE "issues"."deleted_at" IS NULL AND "issues"."project_id" = $1 AND ("issues"."state" IN ('opened')) AND "issues"."confidential" = $2
    --> /home/user/gitlab/gdk/gitlab/spec/support/query_recorder.rb:19:in `callback'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/fanout.rb:127:in `finish'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/fanout.rb:46:in `block in finish'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/fanout.rb:46:in `each'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/fanout.rb:46:in `finish'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/instrumenter.rb:36:in `finish'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications/instrumenter.rb:25:in `instrument'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract_adapter.rb:478:in `log'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:601:in `exec_cache'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:585:in `execute_and_clear'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `exec_query'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:356:in `select'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:32:in `select_all'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/query_cache.rb:68:in `block in select_all'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/query_cache.rb:83:in `cache_sql'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/connection_adapters/abstract/query_cache.rb:68:in `select_all'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/relation/calculations.rb:270:in `execute_simple_calculation'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/relation/calculations.rb:227:in `perform_calculation'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/relation/calculations.rb:133:in `calculate'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activerecord-4.2.8/lib/active_record/relation/calculations.rb:48:in `count'
    --> /home/user/gitlab/gdk/gitlab/app/services/base_count_service.rb:20:in `uncached_count'
    --> /home/user/gitlab/gdk/gitlab/app/services/base_count_service.rb:12:in `block in count'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:299:in `block in fetch'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:585:in `block in save_block_result_to_cache'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:547:in `block in instrument'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/notifications.rb:166:in `instrument'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:547:in `instrument'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:584:in `save_block_result_to_cache'
    --> /home/user/.rbenv/versions/2.3.5/lib/ruby/gems/2.3.0/gems/activesupport-4.2.8/lib/active_support/cache.rb:299:in `fetch'
    --> /home/user/gitlab/gdk/gitlab/app/services/base_count_service.rb:12:in `count'
    --> /home/user/gitlab/gdk/gitlab/app/models/project.rb:1296:in `open_issues_count'

Testing query counts in the Rails console

During development, it can be challenging to identify and count database queries directly in the Rails console output. QueryRecorder can be used interactively to help analyze and optimize query performance before writing tests.

This is particularly useful when:

  • Debugging N+1 queries during feature development
  • Comparing different preloading strategies
  • Validating query optimizations before committing code

The QueryRecorder helper is not automatically loaded in the Rails console, so you must require it first:

ruby
# Important: Require the QueryRecorder helper (not loaded by default)
require './spec/support/helpers/query_recorder.rb'

# Example: Analyzing query counts for different preloading strategies
result = {}
package_files = Packages::PackageFile.limit(5)

# Create a helper to count queries
query_counter = proc do |&query_block|
  ActiveRecord::QueryRecorder.new(&query_block).data.map { |_, v| v[:count] }.reduce(&:+)
end

# Test different approaches
result['without preloading'] = query_counter.call { package_files.map(&:package) }
result['with preload(:package)'] = query_counter.call { package_files.preload(:package).map(&:package) }
result['with includes(package: :project)'] = query_counter.call { package_files.includes(package: :project).map(&:package) }

# View results
result
# => {"without preloading"=>5, "with preload(:package)"=>2, "with includes(package: :project)"=>2}

# Find the most efficient approach
result.min { |a, b| a.second <=> b.second }
# => ["with preload(:package)", 2]

This approach allows you to quickly test and compare different query strategies during development, helping you choose the most efficient implementation before writing your tests and code.

See also