Change in behavior in activerecord from 6.1 to 7.0+

[mrsimo]

Description of the bug

In Rails 6.1 (and 6.0) there used to be an ActiveRecord span for each read query in the form of Model.find_by_sql. We found a few uses for this span, even if the underlaying query was also reported by the lower level library instrumentation as well.

With Rails 7.0 this has changed and only a few queries have this. For instance, Post.first doesn't create a Post.find_by_sql span, but a post.comments does create a Comment.find_by_sql. In Rails 6.1 there'd both of them.

Share details about your runtime

My reproduction steps were run with ruby 3.3.4 (2024-07-09 revision be1089c8ec) [arm64-darwin23], latest opentelemetry gems and various Rails versions (as seen in the script).

Share a simplified reproduction if possible

Here's a gist with a script to reproduce this. The output:

❯ for rails in 6.1 7.0 7.1 7.2; do echo "Rails version: $rails"; RAILS_VERSION=$rails ruby run.rb 1> /dev/null; done
Rails version: 6.1
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `posts`.* FROM `posts` ORDER BY `posts`.`id` ASC LIMIT ?"}
OpenTelemetry::Instrumentation::ActiveRecord: Post.find_by_sql - {}
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `comments`.* FROM `comments` WHERE `comments`.`post_id` = ?"}
OpenTelemetry::Instrumentation::ActiveRecord: Comment.find_by_sql - {}
Rails version: 7.0
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `posts`.* FROM `posts` ORDER BY `posts`.`id` ASC LIMIT ?"}
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `comments`.* FROM `comments` WHERE `comments`.`post_id` = ?"}
OpenTelemetry::Instrumentation::ActiveRecord: Comment.find_by_sql - {}
Rails version: 7.1
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `posts`.* FROM `posts` ORDER BY `posts`.`id` ASC LIMIT ?"}
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `comments`.* FROM `comments` WHERE `comments`.`post_id` = ?"}
OpenTelemetry::Instrumentation::ActiveRecord: Comment.find_by_sql - {}
Rails version: 7.2
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `posts`.* FROM `posts` ORDER BY `posts`.`id` ASC LIMIT ?"}
OpenTelemetry::Instrumentation::Mysql2: select - {"db.statement"=>"SELECT `comments`.* FROM `comments` WHERE `comments`.`post_id` = ?"}
OpenTelemetry::Instrumentation::ActiveRecord: Comment.find_by_sql - {}

[mrsimo]

In case it's helpful, what I've seen:

• The activerecord instrumentation patches the find_by_sql method. In Rails 6.1 this is pretty much the only method in ActiveRecord::Querying. Rails 7.0 adds some methods, Rails 7.1 adds some more.

• These are simplified (only activerecord/opentelemetry-related lines) stack traces I've been able to pull out from running a basic User.first in 6.1 vs 7.0:

  # In rails 6.1
  opentelemetry-instrumentation-active_record-0.7.0/lib/opentelemetry/instrumentation/active_record/patches/querying.rb:22:in `find_by_sql'
  activerecord-6.1.7.8/lib/active_record/relation.rb:843:in `block in exec_queries'
  activerecord-6.1.7.8/lib/active_record/relation.rb:861:in `skip_query_cache_if_necessary'
  activerecord-6.1.7.8/lib/active_record/relation.rb:828:in `exec_queries'
  activerecord-6.1.7.8/lib/active_record/relation.rb:631:in `load'
  activerecord-6.1.7.8/lib/active_record/relation.rb:249:in `records'
  activerecord-6.1.7.8/lib/active_record/relation.rb:244:in `to_ary'
  activerecord-6.1.7.8/lib/active_record/relation/finder_methods.rb:553:in `find_nth_with_limit'
  activerecord-6.1.7.8/lib/active_record/relation/finder_methods.rb:538:in `find_nth'
  activerecord-6.1.7.8/lib/active_record/relation/finder_methods.rb:122:in `first'
  activerecord-6.1.7.8/lib/active_record/querying.rb:22:in `first'
  

  # In Rails 7.0
  # ... Not showing more, seems to differ from this point
  activerecord-7.0.8.4/lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
  activerecord-7.0.8.4/lib/active_record/querying.rb:54:in `_query_by_sql'
  activerecord-7.0.8.4/lib/active_record/relation.rb:942:in `block in exec_main_query'
  activerecord-7.0.8.4/lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
  activerecord-7.0.8.4/lib/active_record/relation.rb:928:in `exec_main_query'
  activerecord-7.0.8.4/lib/active_record/relation.rb:914:in `block in exec_queries'
  activerecord-7.0.8.4/lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
  activerecord-7.0.8.4/lib/active_record/relation.rb:908:in `exec_queries'
  activerecord-7.0.8.4/lib/active_record/relation.rb:695:in `load'
  activerecord-7.0.8.4/lib/active_record/relation.rb:250:in `records'
  activerecord-7.0.8.4/lib/active_record/relation.rb:245:in `to_ary'
  activerecord-7.0.8.4/lib/active_record/relation/finder_methods.rb:549:in `find_nth_with_limit'
  activerecord-7.0.8.4/lib/active_record/relation/finder_methods.rb:534:in `find_nth'
  activerecord-7.0.8.4/lib/active_record/relation/finder_methods.rb:146:in `first'
  activerecord-7.0.8.4/lib/active_record/querying.rb:22:in `first'
  
  

  Something differs after QueryCache#select_all and ends up executing Querying#_query_by_sql instead of Querying#find_by_sql.

• The queries that do end up producing the span under Rails 7.0 show this type of stack trace (this is User#company from our app, defined as a belongs_to :company):

  # Rails 6.1
  opentelemetry-instrumentation-active_record-0.7.0/lib/opentelemetry/instrumentation/active_record/patches/querying.rb:22:in `find_by_sql'
  activerecord-6.1.7.8/lib/active_record/statement_cache.rb:150:in `execute'
  activerecord-6.1.7.8/lib/active_record/associations/association.rb:227:in `find_target'
  activerecord-6.1.7.8/lib/active_record/associations/singular_association.rb:39:in `find_target'
  activerecord-6.1.7.8/lib/active_record/associations/association.rb:174:in `load_target'
  activerecord-6.1.7.8/lib/active_record/associations/association.rb:67:in `reload'
  activerecord-6.1.7.8/lib/active_record/associations/singular_association.rb:9:in `reader'
  activerecord-6.1.7.8/lib/active_record/associations/builder/association.rb:103:in `company'
  

  # Rails 7.0
  opentelemetry-instrumentation-active_record-0.7.4/lib/opentelemetry/instrumentation/active_record/patches/querying.rb:22:in `find_by_sql'
  activerecord-7.0.8.4/lib/active_record/statement_cache.rb:150:in `execute'
  activerecord-7.0.8.4/lib/active_record/associations/association.rb:232:in `find_target'
  activerecord-7.0.8.4/lib/active_record/associations/singular_association.rb:44:in `find_target'
  activerecord-7.0.8.4/lib/active_record/associations/association.rb:173:in `load_target'
  activerecord-7.0.8.4/lib/active_record/associations/association.rb:67:in `reload'
  activerecord-7.0.8.4/lib/active_record/associations/singular_association.rb:11:in `reader'
  activerecord-7.0.8.4/lib/active_record/associations/builder/association.rb:104:in `company'
  

[mrsimo]

I wanted to report this difference in behavior in case it's of interest and if we want to recover this behavior or we're okay. We have found it a bit confusing to have these spans sometimes and sometimes not.

We actually found a few performance problems from N+1 type of queries that didn't actually fire queries because of the ActiveRecord Query Cache, but were a performance problem when running thousands of times in the same request.

Is there any intention of switching the activerecord instrumentation to be based on activesupport notifiactions?

Thank you!

[arielvalentin]

@mrsimo thank you for sharing these findings.

We could use your help making the active record instrumentation better. Would you be interested in helping us by contributing compatibility changes?

[xuan-cao-swi]

Is there any intention to switch ActiveRecord instrumentation to ActiveSupport notifications?

I recall there were gaps between the notification approach and monkey patching from our last discussion. Are these issues still persistent?

The payload name is too general (see discussion), but it might help reduce span name cardinality.

Also, there are discussion about the timing issue from callback.

[github-actions]

👋 This issue has been marked as stale because it has been open with no activity. You can: comment on the issue or remove the stale label to hold stale off for a while, add the keep label to hold stale off permanently, or do nothing. If you do nothing this issue will be closed eventually by the stale bot.

[arielvalentin]

Yes the limitations remain with using notifications.

[mrsimo]

I believe this was fixed in #1184, with recent versions of the activerecord instrumentation library again producing the same amount of spans. I'm going to close this issue!