Instrument ActiveRecord instantiations #334

delner · 2018-01-31T19:28:51Z

For #311 , sometimes ActiveRecord can take significant time instantiating records.

This pull request traces the instantiation.active_record event, for versions of ActiveRecord 4.2+. The additional span has two tags associated with it: active_record.instantiation.class_name and active_record.instantiation.record_count.

Sample output:

dasch

❤️

palazzem · 2018-02-01T17:16:12Z

lib/ddtrace/contrib/active_record/patcher.rb

+            span_type: span_type
+          )
+
+          span.span_type = Datadog::Ext::SQL::TYPE


you can remove this line (or span_type: span_type) since it's a duplicate.

palazzem · 2018-02-01T17:17:12Z

lib/ddtrace/contrib/rails/active_record.rb

+            span_type: span_type
+          )
+
+          span.span_type = Datadog::Ext::SQL::TYPE


palazzem · 2018-02-01T17:19:27Z

lib/ddtrace/contrib/active_record/patcher.rb

+          span = get_option(:tracer).trace(
+            'active_record.instantiation',
+            resource: payload.fetch(:class_name),
+            service: database_service,


I think it should be the main service. If we set the database_service, it will be considered as a latency of your database service (let's say a MySQL Cluster), while what slows down is not the query itself, but ActiveRecord allocating objects.

Makes sense?

Agreed. I thought the same thing (that there wasn't a neat category for this sort of thing.) I'll make that change.

Actually I don't think this is possible, since this ActiveRecord implementation doesn't know what a "main service" is. It might be Sinatra, but it could be a generic Ruby application, too. There's no good way to tell, short of adding an option for specifically configuring service name just for active_record.instantiation, e.g. something like c.use :active_record, ruby_service_name: 'active_record'.

delner · 2018-02-01T18:47:31Z

Another consideration for this pull request... for stand alone implementations of ActiveRecord (e.g. a simple Ruby app that only implements ActiveRecord), we might see disjoint traces for sql and instantiation (which could be undesirable), since they may not have a common parent span. Of course, this probably could be addressed easily by adding a custom trace on top of the code that does the ActiveRecord querying.

This probably won't be an issue for Rails/Sinatra apps with respective tracing enabled though, since they have an implicit parent trace, and thus will simply append themselves to that parent.

palazzem · 2018-02-05T20:54:23Z

lib/ddtrace/contrib/active_record/patcher.rb

 module Datadog
  module Contrib
    module ActiveRecord
      # Patcher enables patching of 'active_record' module.
      module Patcher
        include Base
        register_as :active_record, auto_patch: false
-        option :service_name
+        option :service_name, default: 'active_record', depends_on: [:tracer] do |value|


this is a dangerous breaking change; if people update the gem, metrics will be different and so possible monitors. It means that:

you will see postgresql-cluster what is in real the ActiveRecord instantiation

you will see a new active_record service that is the real query for postgresql.

I think service_name must remain the same as before, and we may find a new option name for the new functionality.

Also not sure the AR part should be called active_record by default. Suppose you create a parent span with name my-app, probably you want to have it my-app instead of active_record (so you don't create another service in your list but you only have my-app that includes the AR latency.

This should handle only the case where you use a standalone AR without a parent span, but in that case maybe we should introduce more the concept of default service for a Tracer.

Rolling back service_name.

palazzem · 2018-02-05T20:56:39Z

lib/ddtrace/contrib/rails/active_record.rb

+          span = tracer.trace(
+            'active_record.instantiation',
+            resource: payload.fetch(:class_name),
+            service: rails_service,


this is fine 👍

Have to change this... I think it should belong to the parent service (if available), to be consistent with the behavior in standalone ActiveRecord. It will fallback to this is the parent name isn't available.

palazzem · 2018-02-05T21:08:20Z

lib/ddtrace/contrib/active_record/patcher.rb

+          span = get_option(:tracer).trace(
+            'active_record.instantiation',
+            resource: payload.fetch(:class_name),
+            service: get_option(:service_name),


In the standalone AR, I would prefer to:

create the span

check if the service name is our default

if not, set the service

if yes, override the span service only if not already set

In this way: ar_service_name > parent service > default value (active_record let's say).

Changing this to be ruby_service_name (not default) > parent service > ruby_service (default)

palazzem · 2018-02-05T21:09:24Z

lib/ddtrace/contrib/active_record/patcher.rb

+          span.start_time = start
+          span.finish(finish)
+        rescue StandardError => e
+          Datadog::Tracer.log.error(e.message)


not sure.... these rescue are in a critical path and can spam users' logs. What about making all of them log.debug?

This is what Rails was already doing for sql. If we change it here, we should probably change it there, too.

Yes I meant all occurrences in this integration (Rails included). I'm worried that for an internal problem we may cause issues like it happened before.

Alright, I can do that then.

palazzem · 2018-02-05T21:13:37Z

test/contrib/rails/database_test.rb

+
+        instantiation_span = spans.first
+        assert_equal(instantiation_span.name, 'active_record.instantiation')
+        assert_equal(instantiation_span.span_type, 'ruby')


The span_type should not be ruby since it's not recognized by our backend. Probably it should be db since it's part of a database transaction? web applies as well, unless you're using AR standalone (that could be just a script).

Ahh, didn't know we can't specify our own types here, which is why I gave it the name I thought more suitable.

Does either web or db apply? I think the answer would be no: instantiating objects is not a web kind of action, nor is it strictly a db thing either. Although it's probably closer to db than to web in the sense that its for the purpose of aiding a DB query, I'd think this could cause us some headaches in the future if, for the purposes of doing statistics or other useful product implementation, we were trying to compare spans of type db to one other, and one isn't actually a DB query at all.

This might be a little out of scope of what this PR is for, but I'd suggest maybe we should add a ruby or custom span type, because there are many spans that aren't web or db. This came up once already while trying to implement GraphQL (which is also neither of those things), so I think this example is adding to a compelling case to examine what span types we have at our disposal.

I would say to remove it then; we can change it to custom instead of ruby.

palazzem

I think this integration is ready in this state. We just need to address a couple of comments and we're ready to go!

palazzem · 2018-02-07T11:09:10Z

test/contrib/rails/database_test.rb

+
+        instantiation_span = spans.first
+        assert_equal(instantiation_span.name, 'active_record.instantiation')
+        assert_equal(instantiation_span.span_type, 'ruby')


I would say to remove it then; we can change it to custom instead of ruby.

palazzem · 2018-02-07T11:14:24Z

lib/ddtrace/contrib/active_record/patcher.rb

@@ -1,11 +1,19 @@
+require 'ddtrace/contrib/rails/utils'


do we need to require these modules if the patch() is not called?

Hmmm perhaps not. I think I'll move this into patch.

palazzem · 2018-02-07T11:19:58Z

lib/ddtrace/contrib/active_record/patcher.rb

+        #       which isn't a good idea at initialization time.
+        def self.database_service_name
+          @database_service_name ||= (get_option(:service_name) || adapter_name).tap do |name|
+            get_option(:tracer).set_service_info(name, 'active_record', Ext::AppTypes::DB)


set_service_info is called only once, correct?

Yeah, that's what this does, unless you change the service_name, in which case this would run again.

totally legit then

palazzem · 2018-02-07T12:36:41Z

lib/ddtrace/contrib/active_record/patcher.rb

+            span_type: Datadog::Ext::Ruby::TYPE
+          )
+
+          # Inherit service name from parent, if available.


👍 I think this is a better default. In general we expect this to be child of something else, though the corner case is well covered with active_record default. Furthermore, if someone wants to change and split the service, they can. So we provide a reasonable default that is easy to configure.

palazzem · 2018-02-07T12:59:00Z

lib/ddtrace/contrib/active_record/patcher.rb

+        option :service_name do |value|
+          value.tap { @database_service_name = nil }
+        end
+        option :ruby_service_name


I'm not entirely sure to keep ruby_ as a prefix, since it's too generic. If we check what this integration is, we can state that ActiveRecord is an architectural pattern that stores in-memory object data in relational databases (ref). In the case of Rails, this pattern is used to implement the ORM. I think we can assume that the most common case is to use it to store data in-memory (or somewhere), so we may use different names such as:

active_record_name

orm_service_name (I prefer this one because it keeps the service_name suffix that is clear in our terminology + orm_ has a specific meaning that is generic enough to cover instantiations and any other operation we may have in the future)

What do you think @delner ?

I like orm_service_name. Ill change that.

one thing I forgot in the review is that we need to update also the documentation with the new option

…by type

…e to custom.

palazzem · 2018-02-08T18:14:29Z

lib/ddtrace/ext/ruby.rb

+module Datadog
+  module Ext
+    module Ruby
+      TYPE = 'ruby'.freeze


I think this one is not required.

Will remove.

palazzem · 2018-02-08T18:15:10Z

lib/ddtrace/contrib/active_record/patcher.rb

+          end
+        end
+
+        def instantiation_tracing_supported?


do we want to use that also to avoid ActiveSupport::Notifications calls?

Yes, will use this to prevent unnecessary instrument calls.

palazzem

Good to go! thank you very much!

delner added enhancement integrations Involves tracing integrations do-not-merge/WIP Not ready for merge labels Jan 31, 2018

delner added this to the 0.11.2 milestone Jan 31, 2018

delner self-assigned this Jan 31, 2018

delner mentioned this pull request Jan 31, 2018

Track Active Record instantiations #311

Closed

delner removed the do-not-merge/WIP Not ready for merge label Jan 31, 2018

delner requested a review from palazzem January 31, 2018 20:09

delner force-pushed the delner/instrument_active_record_instantiation branch 2 times, most recently from 1909df6 to 58a73c9 Compare February 1, 2018 02:30

dasch approved these changes Feb 1, 2018

View reviewed changes

palazzem reviewed Feb 1, 2018

View reviewed changes

palazzem modified the milestones: 0.11.2, 0.11.3 Feb 2, 2018

delner modified the milestones: 0.11.3, 0.12.0 Feb 5, 2018

delner changed the base branch from master to 0.12-dev February 5, 2018 18:57

delner added feature Involves a product feature and removed enhancement labels Feb 5, 2018

delner force-pushed the delner/instrument_active_record_instantiation branch from 2f2eac7 to 8770b9d Compare February 5, 2018 19:24

palazzem removed the feature Involves a product feature label Feb 5, 2018

palazzem suggested changes Feb 5, 2018

View reviewed changes

delner force-pushed the delner/instrument_active_record_instantiation branch 3 times, most recently from 56f433c to 88361a6 Compare February 6, 2018 22:25

palazzem suggested changes Feb 7, 2018

View reviewed changes

delner force-pushed the delner/instrument_active_record_instantiation branch 2 times, most recently from b1e0f1a to e5fe4cd Compare February 7, 2018 16:22

delner force-pushed the delner/instrument_active_record_instantiation branch 2 times, most recently from 2748235 to e3e4da1 Compare February 7, 2018 21:57

delner added 9 commits February 8, 2018 11:17

Added: Instrumentation for Rails 4.2+ ActiveRecord instantiation

b5adf27

Added: Instrumentation for non-Rails ActiveRecord 4.2+ instantiation

73589e7

Added: Ext::Ruby type

ae14f82

Changed: Rails AR instantiation span to use Rails service name and ru…

5769bc3

…by type

Added: database_name option to ActiveRecord integration

a6c731c

Changed: How service is set for ActiveRecord spans.

0d08915

Changed: ActiveRecord ruby_service_name to orm_service_name, span typ…

8b9a7c3

…e to custom.

Added: instantiation_tracing_supported? to improve feature detection

c2e8329

Added: orm_service_name option to ActiveRecord documentation.

8a217be

delner force-pushed the delner/instrument_active_record_instantiation branch from e3e4da1 to 8a217be Compare February 8, 2018 16:21

palazzem reviewed Feb 8, 2018

View reviewed changes

delner added 2 commits February 8, 2018 13:24

Removed: Ext::Ruby

520c930

Changed: Instrument instantiation only if supported.

63c1b48

palazzem approved these changes Feb 8, 2018

View reviewed changes

delner merged commit 3e85f40 into 0.12-dev Feb 8, 2018

delner deleted the delner/instrument_active_record_instantiation branch February 9, 2018 18:51

Instrument ActiveRecord instantiations #334

Instrument ActiveRecord instantiations #334

Conversation

delner commented Jan 31, 2018 • edited

dasch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delner Feb 1, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delner commented Feb 1, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delner Feb 6, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delner Feb 6, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

palazzem left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

palazzem left a comment

Choose a reason for hiding this comment

delner commented Jan 31, 2018 •

edited

delner Feb 1, 2018 •

edited

delner commented Feb 1, 2018 •

edited

delner Feb 6, 2018 •

edited

delner Feb 6, 2018 •

edited