From 312d5244bf584abc94a0adaafa7bd06ed192d24c Mon Sep 17 00:00:00 2001 From: fallwith Date: Tue, 24 Jan 2023 22:36:39 -0800 Subject: [PATCH 1/2] Active Job notifications subscriber Subscribe to Active Job notifications and process the 7 (at the time of Rails v7.1.0.0.alpha) related events to produce additional instrumentation for the library. --- CHANGELOG.md | 2 + .../agent/instrumentation/active_job.rb | 15 +- .../instrumentation/active_job_subscriber.rb | 55 +++++ .../active_job_subscriber_test.rb | 14 ++ .../rails/active_job_subscriber.rb | 201 ++++++++++++++++++ test/simplecov_test_helper.rb | 9 +- 6 files changed, 294 insertions(+), 2 deletions(-) create mode 100644 lib/new_relic/agent/instrumentation/active_job_subscriber.rb create mode 100644 test/new_relic/agent/instrumentation/active_job_subscriber_test.rb create mode 100644 test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb diff --git a/CHANGELOG.md b/CHANGELOG.md index f2c57ec993..22884204c9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ The upcoming release of the agent introduces additional Ruby on Rails instrument - Action Dispatch (for middleware) [PR#1745](https://github.com/newrelic/newrelic-ruby-agent/pull/1745) - Action Mailbox (for sending mail) [PR#1740](https://github.com/newrelic/newrelic-ruby-agent/pull/1740) - Action Mailer (for routing mail) [PR#1740](https://github.com/newrelic/newrelic-ruby-agent/pull/1740) + - Active Job (for background jobs) [PR#1742](https://github.com/newrelic/newrelic-ruby-agent/pull/1761) - Active Support (for caching operations) [PR#1742](https://github.com/newrelic/newrelic-ruby-agent/pull/1742) The instrumentations for each of these libaries are all enabled by default, but can be independently disabled via configuration by using the following parameters: @@ -24,6 +25,7 @@ The upcoming release of the agent introduces additional Ruby on Rails instrument | `disable_action_dispatch` | `false` | If `true`, disables Action Dispatch instrumentation. | | `disable_action_mailbox` | `false` | If `true`, disables Action Mailbox instrumentation. | | `disable_action_mailer` | `false` | If `true`, disables Action Mailer instrumentation. | + | `disable_activejob` | `false` | If `true`, disables Active Job instrumentation. | | `disable_active_support` | `false` | If `true`, disables Active Support instrumentation. | ## 8.15.0 diff --git a/lib/new_relic/agent/instrumentation/active_job.rb b/lib/new_relic/agent/instrumentation/active_job.rb index f6866769c6..d09d3cfa6e 100644 --- a/lib/new_relic/agent/instrumentation/active_job.rb +++ b/lib/new_relic/agent/instrumentation/active_job.rb @@ -12,7 +12,7 @@ end executes do - NewRelic::Agent.logger.info('Installing ActiveJob instrumentation') + NewRelic::Agent.logger.info('Installing base ActiveJob instrumentation') ActiveSupport.on_load(:active_job) do ActiveJob::Base.around_enqueue do |job, block| @@ -26,6 +26,19 @@ NewRelic::Agent::PrependSupportability.record_metrics_for(ActiveJob::Base) end end + + executes do + if defined?(ActiveSupport) && + ActiveJob.respond_to?(:gem_version) && + ActiveJob.gem_version >= Gem::Version.new('6.0.0') && + !NewRelic::Agent.config[:disable_activejob] && + !NewRelic::Agent::Instrumentation::ActiveJobSubscriber.subscribed? + NewRelic::Agent.logger.info('Installing notifications based ActiveJob instrumentation') + + ActiveSupport::Notifications.subscribe(/\A[^\.]+\.active_job\z/, + NewRelic::Agent::Instrumentation::ActiveJobSubscriber.new) + end + end end module NewRelic diff --git a/lib/new_relic/agent/instrumentation/active_job_subscriber.rb b/lib/new_relic/agent/instrumentation/active_job_subscriber.rb new file mode 100644 index 0000000000..452544a3fc --- /dev/null +++ b/lib/new_relic/agent/instrumentation/active_job_subscriber.rb @@ -0,0 +1,55 @@ +# This file is distributed under New Relic's license terms. +# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details. +# frozen_string_literal: true + +require 'new_relic/agent/instrumentation/notifications_subscriber' + +module NewRelic + module Agent + module Instrumentation + class ActiveJobSubscriber < NotificationsSubscriber + PAYLOAD_KEYS = %i[adapter db_runtime error job wait] + + def start_segment(name, id, payload) + segment = Tracer.start_segment(name: metric_name(name, payload)) + + PAYLOAD_KEYS.each do |key| + segment.params[key] = payload[key] if payload.key?(key) + end + + push_segment(id, segment) + end + + def finish_segment(id, payload) + if segment = pop_segment(id) + if exception = exception_object(payload) + segment.notice_error(exception) + end + segment.finish + end + end + + def metric_name(name, payload) + queue = payload[:job].queue_name + method = method_from_name(name) + "Ruby/ActiveJob/#{queue}/#{method}" + end + + PATTERN = /\A([^\.]+)\.active_job\z/ + UNKNOWN = 'unknown'.freeze + + METHOD_NAME_MAPPING = Hash.new do |h, k| + if PATTERN =~ k + h[k] = $1 + else + h[k] = UNKNOWN + end + end + + def method_from_name(name) + METHOD_NAME_MAPPING[name] + end + end + end + end +end diff --git a/test/new_relic/agent/instrumentation/active_job_subscriber_test.rb b/test/new_relic/agent/instrumentation/active_job_subscriber_test.rb new file mode 100644 index 0000000000..97f2d22b64 --- /dev/null +++ b/test/new_relic/agent/instrumentation/active_job_subscriber_test.rb @@ -0,0 +1,14 @@ +# This file is distributed under New Relic's license terms. +# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details. +# frozen_string_literal: true + +require_relative '../../../test_helper' +require 'new_relic/agent/instrumentation/active_job_subscriber' + +if defined?(ActiveJob) && + ActiveJob.respond_to?(:gem_version) && + ActiveJob.gem_version >= Gem::Version.new('6.0.0') + require_relative 'rails/active_job_subscriber' +else + puts "Skipping tests in #{__FILE__} because ActiveJob is unavailable or < 6.0" +end diff --git a/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb b/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb new file mode 100644 index 0000000000..9c25910496 --- /dev/null +++ b/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb @@ -0,0 +1,201 @@ +# This file is distributed under New Relic's license terms. +# See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details. +# frozen_string_literal: true + +require_relative '../../../../test_helper' +require 'new_relic/agent/instrumentation/active_job_subscriber' + +module NewRelic::Agent::Instrumentation + class RetryMe < StandardError; end + class DiscardMe < StandardError; end + + class TestJob < ActiveJob::Base + retry_on RetryMe + + discard_on DiscardMe + + def perform(error = nil) + raise error if error + + rand(1138) + end + end + + class ActiveJobSubscriberTest < Minitest::Test + NAME = 'perform.active_job' + ID = 71741 + SUBSCRIBER = NewRelic::Agent::Instrumentation::ActiveJobSubscriber.new + + def test_start + in_transaction do |txn| + time = Time.now.to_f + SUBSCRIBER.start(NAME, ID, {job: TestJob.new}) + segment = txn.segments.last + + assert_in_delta time, segment.start_time + assert_equal 'Ruby/ActiveJob/default/perform', segment.name + end + end + + def test_start_when_not_traced + SUBSCRIBER.state.stub :is_execution_traced?, false do + in_transaction do |txn| + SUBSCRIBER.start(NAME, ID, {}) + + assert_empty txn.segments + end + end + end + + def test_start_with_exception_raised + logger = MiniTest::Mock.new + + NewRelic::Agent.stub :logger, logger do + logger.expect :error, nil, [/Error during .* callback/] + logger.expect :log_exception, nil, [:error, ArgumentError] + + in_transaction do |txn| + SUBSCRIBER.stub :start_segment, -> { raise 'kaboom' } do + SUBSCRIBER.start(NAME, ID, {}) + end + + assert_equal 1, txn.segments.size + end + end + logger.verify + end + + def test_segment_naming_with_unknown_method + assert_equal 'Ruby/ActiveJob/default/unknown', + SUBSCRIBER.send(:metric_name, 'indecipherable', {job: TestJob.new}) + end + + def test_finish + in_transaction do |txn| + started_segment = NewRelic::Agent::Tracer.start_transaction_or_segment(name: NAME, category: :testing) + SUBSCRIBER.push_segment(ID, started_segment) + + time = Time.now.to_f + SUBSCRIBER.finish(NAME, ID, {}) + segment = txn.segments.last + + assert_in_delta time, segment.end_time + assert_predicate(segment, :finished?) + end + end + + def test_finish_with_exception_payload + skip_unless_minitest5_or_above + + exception_object = StandardError.new + noticed = false + segment = MiniTest::Mock.new + segment.expect :notice_error, nil, [exception_object] + SUBSCRIBER.stub(:pop_segment, segment, [ID]) do + SUBSCRIBER.finish(NAME, ID, {exception_object: exception_object}) + end + + segment.verify + end + + def test_finish_with_exception_raised + logger = MiniTest::Mock.new + + NewRelic::Agent.stub :logger, logger do + logger.expect :error, nil, [/Error during .* callback/] + logger.expect :log_exception, nil, [:error, RuntimeError] + + in_transaction do |txn| + SUBSCRIBER.state.stub :is_execution_traced?, -> { raise 'kaboom' } do + SUBSCRIBER.finish(NAME, ID, {}) + end + + assert_equal 1, txn.segments.size + end + end + logger.verify + end + + def test_finish_when_not_tracing + state = MiniTest::Mock.new + state.expect :is_execution_traced?, false + + SUBSCRIBER.stub :state, state do + assert_nil SUBSCRIBER.finish(NAME, ID, {}) + end + end + + def test_finish_segment_when_a_segment_does_not_exist + SUBSCRIBER.stub :pop_segment, nil, [ID] do + assert_nil SUBSCRIBER.send(:finish_segment, ID, {}) + end + end + + # perform.active_job + def test_an_actual_job_event_perform + job = TestJob.new + in_transaction do |txn| + job.perform_now + validate_transaction(txn, 'perform') + end + end + + # enqueue_at.active_job + def test_an_actual_job_event_enqueue_at + in_transaction do |txn| + TestJob.set(wait_until: 7.hours.from_now).perform_later + validate_transaction(txn, 'enqueue_at') + end + end + + # enqueue.active_job + def test_an_actual_job_event_enqueue + in_transaction do |txn| + TestJob.perform_later + validate_transaction(txn, 'enqueue') + end + end + + # perform_start.active_job + # enqueue_retry.active_job + def test_an_actual_job_event_retry + in_transaction do |txn| + TestJob.perform_now(RetryMe) + validate_transaction(txn, %w[enqueue_retry perform_start]) + end + end + + # discard.active_job + def test_an_actual_job_event_retry + in_transaction do |txn| + TestJob.perform_now(DiscardMe) + validate_transaction(txn, 'discard') + end + end + + # TODO: test for retry_stopped + # retry_stopped.active_job + # def test_an_actual_job_event_retry + # in_transaction do |txn| + # # ??? + # validate_transaction(txn, 'retry_stopped') + # end + # end + + private + + def validate_transaction(txn, methods = []) + methods = Array(methods) + segments = txn.segments.select { |s| s.name.start_with?('Ruby/ActiveJob') } + + refute_empty segments + + methods.each do |method| + segment = segments.detect { |s| s.name == "Ruby/ActiveJob/default/#{method}" } + + assert segment + assert_equal 'ActiveJob::QueueAdapters::AsyncAdapter', segment.params[:adapter].class.name + end + end + end +end diff --git a/test/simplecov_test_helper.rb b/test/simplecov_test_helper.rb index b4e0b2aa72..6dff7bba1e 100644 --- a/test/simplecov_test_helper.rb +++ b/test/simplecov_test_helper.rb @@ -7,4 +7,11 @@ # required Ruby >= 2.5.0 and Ruby 2.6.0 was marked for EOL SIMPLECOV_MIN_RUBY_VERSION = '2.7.0' -require 'simplecov' if RUBY_VERSION >= SIMPLECOV_MIN_RUBY_VERSION +begin + require 'simplecov' if RUBY_VERSION >= SIMPLECOV_MIN_RUBY_VERSION +rescue LoadError => e + puts + puts "SimpleCov requested by Ruby #{RUBY_VERSION} which is >=#{SIMPLECOV_MIN_RUBY_VERSION} " + puts "but the gem is not available. #{e.class}: #{e.message}" + puts +end From 6e2aaf5f00b3447670f68fe508a2d7c52bd6263d Mon Sep 17 00:00:00 2001 From: fallwith Date: Wed, 25 Jan 2023 12:00:49 -0800 Subject: [PATCH 2/2] ActiveJob notifications PR feedback - leverage the base NotificationsSubscriber class better - standardize on NewRelic::UNKNOWN - update test names - simplify TODO comment --- .../instrumentation/active_job_subscriber.rb | 18 +-- .../rails/active_job_subscriber.rb | 121 +----------------- 2 files changed, 9 insertions(+), 130 deletions(-) diff --git a/lib/new_relic/agent/instrumentation/active_job_subscriber.rb b/lib/new_relic/agent/instrumentation/active_job_subscriber.rb index 452544a3fc..a8384535be 100644 --- a/lib/new_relic/agent/instrumentation/active_job_subscriber.rb +++ b/lib/new_relic/agent/instrumentation/active_job_subscriber.rb @@ -10,23 +10,10 @@ module Instrumentation class ActiveJobSubscriber < NotificationsSubscriber PAYLOAD_KEYS = %i[adapter db_runtime error job wait] - def start_segment(name, id, payload) - segment = Tracer.start_segment(name: metric_name(name, payload)) - + def add_segment_params(segment, payload) PAYLOAD_KEYS.each do |key| segment.params[key] = payload[key] if payload.key?(key) end - - push_segment(id, segment) - end - - def finish_segment(id, payload) - if segment = pop_segment(id) - if exception = exception_object(payload) - segment.notice_error(exception) - end - segment.finish - end end def metric_name(name, payload) @@ -36,13 +23,12 @@ def metric_name(name, payload) end PATTERN = /\A([^\.]+)\.active_job\z/ - UNKNOWN = 'unknown'.freeze METHOD_NAME_MAPPING = Hash.new do |h, k| if PATTERN =~ k h[k] = $1 else - h[k] = UNKNOWN + h[k] = NewRelic::UNKNOWN end end diff --git a/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb b/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb index 9c25910496..b80081b465 100644 --- a/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb +++ b/test/new_relic/agent/instrumentation/rails/active_job_subscriber.rb @@ -26,113 +26,13 @@ class ActiveJobSubscriberTest < Minitest::Test ID = 71741 SUBSCRIBER = NewRelic::Agent::Instrumentation::ActiveJobSubscriber.new - def test_start - in_transaction do |txn| - time = Time.now.to_f - SUBSCRIBER.start(NAME, ID, {job: TestJob.new}) - segment = txn.segments.last - - assert_in_delta time, segment.start_time - assert_equal 'Ruby/ActiveJob/default/perform', segment.name - end - end - - def test_start_when_not_traced - SUBSCRIBER.state.stub :is_execution_traced?, false do - in_transaction do |txn| - SUBSCRIBER.start(NAME, ID, {}) - - assert_empty txn.segments - end - end - end - - def test_start_with_exception_raised - logger = MiniTest::Mock.new - - NewRelic::Agent.stub :logger, logger do - logger.expect :error, nil, [/Error during .* callback/] - logger.expect :log_exception, nil, [:error, ArgumentError] - - in_transaction do |txn| - SUBSCRIBER.stub :start_segment, -> { raise 'kaboom' } do - SUBSCRIBER.start(NAME, ID, {}) - end - - assert_equal 1, txn.segments.size - end - end - logger.verify - end - def test_segment_naming_with_unknown_method - assert_equal 'Ruby/ActiveJob/default/unknown', + assert_equal 'Ruby/ActiveJob/default/Unknown', SUBSCRIBER.send(:metric_name, 'indecipherable', {job: TestJob.new}) end - def test_finish - in_transaction do |txn| - started_segment = NewRelic::Agent::Tracer.start_transaction_or_segment(name: NAME, category: :testing) - SUBSCRIBER.push_segment(ID, started_segment) - - time = Time.now.to_f - SUBSCRIBER.finish(NAME, ID, {}) - segment = txn.segments.last - - assert_in_delta time, segment.end_time - assert_predicate(segment, :finished?) - end - end - - def test_finish_with_exception_payload - skip_unless_minitest5_or_above - - exception_object = StandardError.new - noticed = false - segment = MiniTest::Mock.new - segment.expect :notice_error, nil, [exception_object] - SUBSCRIBER.stub(:pop_segment, segment, [ID]) do - SUBSCRIBER.finish(NAME, ID, {exception_object: exception_object}) - end - - segment.verify - end - - def test_finish_with_exception_raised - logger = MiniTest::Mock.new - - NewRelic::Agent.stub :logger, logger do - logger.expect :error, nil, [/Error during .* callback/] - logger.expect :log_exception, nil, [:error, RuntimeError] - - in_transaction do |txn| - SUBSCRIBER.state.stub :is_execution_traced?, -> { raise 'kaboom' } do - SUBSCRIBER.finish(NAME, ID, {}) - end - - assert_equal 1, txn.segments.size - end - end - logger.verify - end - - def test_finish_when_not_tracing - state = MiniTest::Mock.new - state.expect :is_execution_traced?, false - - SUBSCRIBER.stub :state, state do - assert_nil SUBSCRIBER.finish(NAME, ID, {}) - end - end - - def test_finish_segment_when_a_segment_does_not_exist - SUBSCRIBER.stub :pop_segment, nil, [ID] do - assert_nil SUBSCRIBER.send(:finish_segment, ID, {}) - end - end - # perform.active_job - def test_an_actual_job_event_perform + def test_perform_active_job job = TestJob.new in_transaction do |txn| job.perform_now @@ -141,7 +41,7 @@ def test_an_actual_job_event_perform end # enqueue_at.active_job - def test_an_actual_job_event_enqueue_at + def test_enqueue_at_active_job in_transaction do |txn| TestJob.set(wait_until: 7.hours.from_now).perform_later validate_transaction(txn, 'enqueue_at') @@ -149,7 +49,7 @@ def test_an_actual_job_event_enqueue_at end # enqueue.active_job - def test_an_actual_job_event_enqueue + def test_enqueue_active_job in_transaction do |txn| TestJob.perform_later validate_transaction(txn, 'enqueue') @@ -158,7 +58,7 @@ def test_an_actual_job_event_enqueue # perform_start.active_job # enqueue_retry.active_job - def test_an_actual_job_event_retry + def test_perform_start_active_job_and_enqueue_retry_active_job in_transaction do |txn| TestJob.perform_now(RetryMe) validate_transaction(txn, %w[enqueue_retry perform_start]) @@ -166,21 +66,14 @@ def test_an_actual_job_event_retry end # discard.active_job - def test_an_actual_job_event_retry + def test_discard_active_job in_transaction do |txn| TestJob.perform_now(DiscardMe) validate_transaction(txn, 'discard') end end - # TODO: test for retry_stopped - # retry_stopped.active_job - # def test_an_actual_job_event_retry - # in_transaction do |txn| - # # ??? - # validate_transaction(txn, 'retry_stopped') - # end - # end + # TODO: test for retry_stopped.active_job private