search

open-telemetry / opentelemetry-ruby-contrib

Contrib Packages for the OpenTelemetry Ruby API and SDK implementation.
https://opentelemetry.io
Apache License 2.0
81 stars 169 forks source link

Change in behavior in activerecord from 6.1 to 7.0+ #1183

Open mrsimo opened 3 weeks ago

mrsimo commented 3 weeks ago

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 commented 3 weeks ago

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

mrsimo commented 3 weeks ago

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 commented 3 weeks ago

@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 commented 3 weeks ago

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.