Merge pull request #102 from hennevogel/feature/activejob-instrumentation

hennevogel · web-flow · commit 12f630c192c4 · 2020-05-11T15:42:57.000+02:00
Introduces ActiveJobSubscriber
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -10,6 +10,9 @@ For the full commit log, [see here](https://github.com/influxdata/influxdb-rails
   `ignored_environments` do disable instrumentation
 - Simplified spec with a PORO test client
 - Implement `instantiation.active_record` subscriber (https://guides.rubyonrails.org/active_support_instrumentation.html#instantiation-active-record)
+- Implement `enqueue.active_job` subscriber (https://guides.rubyonrails.org/active_support_instrumentation.html#enqueue-active-job)
+- Implement `perform_start.active_job` subscriber (https://guides.rubyonrails.org/active_support_instrumentation.html#perform-start-active-job)
+- Implement `perform.active_job` subscriber (https://guides.rubyonrails.org/active_support_instrumentation.html#perform-active-job)
 
 ## v1.0.0, released 2019-10-23
 The Final release, no code changes.
diff --git a/influxdb-rails.gemspec b/influxdb-rails.gemspec
@@ -27,6 +27,7 @@ Gem::Specification.new do |spec|
   spec.add_runtime_dependency "influxdb", "~> 0.6", ">= 0.6.4"
   spec.add_runtime_dependency "railties", ">= 5.0"
 
+  spec.add_development_dependency "activejob"
   spec.add_development_dependency "activerecord"
   spec.add_development_dependency "bundler", ">= 1.0.0"
   spec.add_development_dependency "fakeweb"
diff --git a/lib/influxdb-rails.rb b/lib/influxdb-rails.rb
@@ -6,6 +6,7 @@
 require "influxdb/rails/middleware/request_subscriber"
 require "influxdb/rails/middleware/sql_subscriber"
 require "influxdb/rails/middleware/active_record_subscriber"
+require "influxdb/rails/middleware/active_job_subscriber"
 require "influxdb/rails/sql/query"
 require "influxdb/rails/version"
 require "influxdb/rails/configuration"
diff --git a/lib/influxdb/rails/middleware/active_job_subscriber.rb b/lib/influxdb/rails/middleware/active_job_subscriber.rb
@@ -0,0 +1,50 @@
+require "influxdb/rails/middleware/subscriber"
+
+module InfluxDB
+  module Rails
+    module Middleware
+      class ActiveJobSubscriber < Subscriber # :nodoc:
+        private
+
+        def values(_start, duration, _payload)
+          value = measure_performance? ? duration : 1
+          {
+            value: value,
+          }
+        end
+
+        def tags(payload)
+          {
+            hook:  short_hook_name,
+            state: job_state(payload),
+            job:   payload[:job].class.name,
+            queue: payload[:job].queue_name,
+          }
+        end
+
+        def short_hook_name
+          return "enqueue" if hook_name.include?("enqueue")
+          return "perform_start" if hook_name.include?("perform_start")
+          return "perform" if hook_name.include?("perform")
+        end
+
+        def job_state(payload)
+          return "failed" if payload[:exception_object]
+
+          case short_hook_name
+          when "enqueue"
+            "queued"
+          when "perform_start"
+            "running"
+          when "perform"
+            "succeeded"
+          end
+        end
+
+        def measure_performance?
+          short_hook_name == "perform"
+        end
+      end
+    end
+  end
+end
diff --git a/lib/influxdb/rails/middleware/active_record_subscriber.rb b/lib/influxdb/rails/middleware/active_record_subscriber.rb
@@ -7,9 +7,9 @@ module Middleware
       class ActiveRecordSubscriber < Subscriber # :nodoc:
         private
 
-        def values(started, finished, payload)
+        def values(_start, duration, payload)
           {
-            value:        ((finished - started) * 1000).ceil,
+            value:        duration,
             record_count: payload[:record_count],
           }
         end
diff --git a/lib/influxdb/rails/middleware/render_subscriber.rb b/lib/influxdb/rails/middleware/render_subscriber.rb
@@ -12,9 +12,9 @@ def short_hook_name
 
         private
 
-        def values(started, finished, payload)
+        def values(_start, duration, payload)
           {
-            value:      ((finished - started) * 1000).ceil,
+            value:      duration,
             count:      payload[:count],
             cache_hits: payload[:cache_hits],
           }
diff --git a/lib/influxdb/rails/middleware/request_subscriber.rb b/lib/influxdb/rails/middleware/request_subscriber.rb
@@ -22,13 +22,13 @@ def tags(payload)
           }
         end
 
-        def values(started, finished, payload)
+        def values(start, duration, payload)
           {
-            controller: ((finished - started) * 1000).ceil,
+            controller: duration,
             view:       (payload[:view_runtime] || 0).ceil,
             db:         (payload[:db_runtime] || 0).ceil,
             started:    InfluxDB.convert_timestamp(
-              started.utc,
+              start.utc,
               configuration.client.time_precision
             ),
           }
diff --git a/lib/influxdb/rails/middleware/sql_subscriber.rb b/lib/influxdb/rails/middleware/sql_subscriber.rb
@@ -11,9 +11,9 @@ def call(_name, started, finished, _unique_id, payload)
 
         private
 
-        def values(started, finished, payload)
+        def values(_start, duration, payload)
           {
-            value: ((finished - started) * 1000).ceil,
+            value: duration,
             sql:   InfluxDB::Rails::Sql::Normalizer.new(payload[:sql]).perform,
           }
         end
diff --git a/lib/influxdb/rails/middleware/subscriber.rb b/lib/influxdb/rails/middleware/subscriber.rb
@@ -25,7 +25,7 @@ def call(_name, start, finish, _id, payload)
 
         def write_metric(start, finish, payload)
           InfluxDB::Rails::Metric.new(
-            values:        values(start, finish, payload),
+            values:        values(start, ((finish - start) * 1000).ceil, payload),
             tags:          tags(payload),
             configuration: configuration,
             timestamp:     finish,
diff --git a/lib/influxdb/rails/railtie.rb b/lib/influxdb/rails/railtie.rb
@@ -4,6 +4,7 @@
 module InfluxDB
   module Rails
     class Railtie < ::Rails::Railtie # :nodoc:
+      # rubocop:disable Metrics/BlockLength
       config.after_initialize do
         InfluxDB::Rails.configure do |config|
           config.environment ||= ::Rails.env
@@ -30,10 +31,14 @@ class Railtie < ::Rails::Railtie # :nodoc:
           "render_collection.action_view"    => Middleware::RenderSubscriber,
           "sql.active_record"                => Middleware::SqlSubscriber,
           "instantiation.active_record"      => Middleware::ActiveRecordSubscriber,
+          "enqueue.active_job"               => Middleware::ActiveJobSubscriber,
+          "perform_start.active_job"         => Middleware::ActiveJobSubscriber,
+          "perform.active_job"               => Middleware::ActiveJobSubscriber,
         }.each do |hook_name, subscriber_class|
           subscribe_to(hook_name, subscriber_class)
         end
       end
+      # rubocop:enable Metrics/BlockLength
 
       def subscribe_to(hook_name, subscriber_class)
         subscriber = subscriber_class.new(InfluxDB::Rails.configuration, hook_name)
diff --git a/lib/influxdb/rails/tags.rb b/lib/influxdb/rails/tags.rb
@@ -24,6 +24,7 @@ def default_tags
         {
           server:   Socket.gethostname,
           app_name: config.application_name,
+          location: :raw,
         }.merge(InfluxDB::Rails.current.tags)
       end
 
diff --git a/spec/requests/active_job_enqueue_metrics_spec.rb b/spec/requests/active_job_enqueue_metrics_spec.rb
@@ -0,0 +1,65 @@
+require File.dirname(__FILE__) + "/../spec_helper"
+
+RSpec.describe "ActiveRecord metrics", type: :request do
+  let(:tags_middleware) do
+    lambda do |tags|
+      tags.merge(tags_middleware: :tags_middleware)
+    end
+  end
+  before do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_environments).and_return(%w[development])
+    allow_any_instance_of(ActionDispatch::Request).to receive(:request_id).and_return(:request_id)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:application_name).and_return(:app_name)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:tags_middleware).and_return(tags_middleware)
+  end
+
+  it "writes metric" do
+    get "/metrics"
+
+    expect_metric(
+      tags:   a_hash_including(
+        location:        "MetricsController#index",
+        hook:            "enqueue",
+        job:             "MetricJob",
+        queue:           "default",
+        state:           "queued",
+        additional_tag:  :value,
+        server:          Socket.gethostname,
+        app_name:        :app_name,
+        tags_middleware: :tags_middleware
+      ),
+      values: a_hash_including(
+        additional_value: :value,
+        request_id:       :request_id,
+        value:            1
+      )
+    )
+  end
+
+  it "includes correct timestamps" do
+    travel_to Time.zone.local(2018, 1, 1, 9, 0, 0)
+
+    get "/metrics"
+
+    expect_metric(
+      tags:      a_hash_including(
+        location: "MetricsController#index",
+        hook:     "enqueue"
+      ),
+      timestamp: 1_514_797_200
+    )
+  end
+
+  it "does not write metric when hook is ignored" do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_hooks).and_return(["enqueue.active_job"])
+
+    get "/metrics"
+
+    expect_no_metric(
+      tags: a_hash_including(
+        location: "MetricsController#index",
+        hook:     "enqueue"
+      )
+    )
+  end
+end
diff --git a/spec/requests/active_job_perform_metrics_spec.rb b/spec/requests/active_job_perform_metrics_spec.rb
@@ -0,0 +1,68 @@
+require File.dirname(__FILE__) + "/../spec_helper"
+
+RSpec.describe "ActiveRecord metrics", type: :request do
+  let(:tags_middleware) do
+    lambda do |tags|
+      tags.merge(tags_middleware: :tags_middleware)
+    end
+  end
+  before do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_environments).and_return(%w[development])
+    allow_any_instance_of(ActionDispatch::Request).to receive(:request_id).and_return(:request_id)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:application_name).and_return(:app_name)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:tags_middleware).and_return(tags_middleware)
+  end
+
+  it "writes metric" do
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_metric(
+      tags:   a_hash_including(
+        location:        "MetricsController#index",
+        hook:            "perform",
+        state:           "succeeded",
+        job:             "MetricJob",
+        queue:           "default",
+        server:          Socket.gethostname,
+        app_name:        :app_name,
+        tags_middleware: :tags_middleware
+      ),
+      values: a_hash_including(
+        value: be_between(0, 30)
+      )
+    )
+  end
+
+  it "includes correct timestamps" do
+    travel_to Time.zone.local(2018, 1, 1, 9, 0, 0)
+
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_metric(
+      tags:      a_hash_including(
+        location: "MetricsController#index",
+        hook:     "perform"
+      ),
+      timestamp: 1_514_797_200
+    )
+  end
+
+  it "does not write metric when hook is ignored" do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_hooks).and_return(["perform.active_job"])
+
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_no_metric(
+      tags: a_hash_including(
+        location: "MetricsController#index",
+        hook:     "perform"
+      )
+    )
+  end
+end
diff --git a/spec/requests/active_job_perform_start_metrics_spec.rb b/spec/requests/active_job_perform_start_metrics_spec.rb
@@ -0,0 +1,68 @@
+require File.dirname(__FILE__) + "/../spec_helper"
+
+RSpec.describe "ActiveRecord metrics", type: :request do
+  let(:tags_middleware) do
+    lambda do |tags|
+      tags.merge(tags_middleware: :tags_middleware)
+    end
+  end
+  before do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_environments).and_return(%w[development])
+    allow_any_instance_of(ActionDispatch::Request).to receive(:request_id).and_return(:request_id)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:application_name).and_return(:app_name)
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:tags_middleware).and_return(tags_middleware)
+  end
+
+  it "writes metric" do
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_metric(
+      tags:   a_hash_including(
+        location:        "MetricsController#index",
+        hook:            "perform_start",
+        state:           "running",
+        job:             "MetricJob",
+        queue:           "default",
+        server:          Socket.gethostname,
+        app_name:        :app_name,
+        tags_middleware: :tags_middleware
+      ),
+      values: a_hash_including(
+        value: 1
+      )
+    )
+  end
+
+  it "includes correct timestamps" do
+    travel_to Time.zone.local(2018, 1, 1, 9, 0, 0)
+
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_metric(
+      tags:      a_hash_including(
+        location: "MetricsController#index",
+        hook:     "perform_start"
+      ),
+      timestamp: 1_514_797_200
+    )
+  end
+
+  it "does not write metric when hook is ignored" do
+    allow_any_instance_of(InfluxDB::Rails::Configuration).to receive(:ignored_hooks).and_return(["perform_start.active_job"])
+
+    perform_enqueued_jobs do
+      get "/metrics"
+    end
+
+    expect_no_metric(
+      tags: a_hash_including(
+        location: "MetricsController#index",
+        hook:     "perform_start"
+      )
+    )
+  end
+end
diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb
@@ -45,6 +45,7 @@
   end
 
   config.include ActiveSupport::Testing::TimeHelpers
+  config.include ActiveJob::TestHelper
   config.include InfluxDB::Rails::Matchers
   config.include InfluxDB::Rails::BrokenClient
 end
diff --git a/spec/support/rails4/app.rb b/spec/support/rails4/app.rb
diff --git a/spec/support/rails5/app.rb b/spec/support/rails5/app.rb
diff --git a/spec/support/rails6/app.rb b/spec/support/rails6/app.rb

Original file line number	Diff line number	Diff line change
`@@ -7,9 +7,9 @@ module Middleware`
`7`	`7`	`class ActiveRecordSubscriber < Subscriber # :nodoc:`
`8`	`8`	`private`
`9`	`9`
`10`		`- def values(started, finished, payload)`
	`10`	`+ def values(_start, duration, payload)`
`11`	`11`	`{`
`12`		`- value: ((finished - started) * 1000).ceil,`
	`12`	`+ value: duration,`
`13`	`13`	`record_count: payload[:record_count],`
`14`	`14`	`}`
`15`	`15`	`end`
Original file line number	Diff line number	Diff line change
`@@ -12,9 +12,9 @@ def short_hook_name`
`12`	`12`
`13`	`13`	`private`
`14`	`14`
`15`		`- def values(started, finished, payload)`
	`15`	`+ def values(_start, duration, payload)`
`16`	`16`	`{`
`17`		`- value: ((finished - started) * 1000).ceil,`
	`17`	`+ value: duration,`
`18`	`18`	`count: payload[:count],`
`19`	`19`	`cache_hits: payload[:cache_hits],`
`20`	`20`	`}`
Original file line number	Diff line number	Diff line change
`@@ -22,13 +22,13 @@ def tags(payload)`
`22`	`22`	`}`
`23`	`23`	`end`
`24`	`24`
`25`		`- def values(started, finished, payload)`
	`25`	`+ def values(start, duration, payload)`
`26`	`26`	`{`
`27`		`- controller: ((finished - started) * 1000).ceil,`
	`27`	`+ controller: duration,`
`28`	`28`	`view: (payload[:view_runtime] \|\| 0).ceil,`
`29`	`29`	`db: (payload[:db_runtime] \|\| 0).ceil,`
`30`	`30`	`started: InfluxDB.convert_timestamp(`
`31`		`- started.utc,`
	`31`	`+ start.utc,`
`32`	`32`	`configuration.client.time_precision`
`33`	`33`	`),`
`34`	`34`	`}`
Original file line number	Diff line number	Diff line change
`@@ -11,9 +11,9 @@ def call(_name, started, finished, _unique_id, payload)`
`11`	`11`
`12`	`12`	`private`
`13`	`13`
`14`		`- def values(started, finished, payload)`
	`14`	`+ def values(_start, duration, payload)`
`15`	`15`	`{`
`16`		`- value: ((finished - started) * 1000).ceil,`
	`16`	`+ value: duration,`
`17`	`17`	`sql: InfluxDB::Rails::Sql::Normalizer.new(payload[:sql]).perform,`
`18`	`18`	`}`
`19`	`19`	`end`