diff --git a/CHANGELOG.md b/CHANGELOG.md index 84168c4c2b..7d5d3ec687 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,17 @@ # New Relic Ruby Agent Release Notes +## Upcoming Release + +This upcoming release of the agent adds instrumentation for Active Support caching operations. + +- **Add Active Support Instrumentation** + + Instrumentation is now automatically provided for all [Active Support caching](https://guides.rubyonrails.org/caching_with_rails.html) operations. Whenever a caching operation is performed, a New Relic segment is created that contains timing information as well as parameters for the cache key, store, and other relevant data. [PR#1742](https://github.com/newrelic/newrelic-ruby-agent/pull/1742) + + | Configuration name | Default | Behavior | + | ----- | ----- | ----- | + | `disable_active_support` | `false` | If `true`, disables Active Support instrumentation. | + ## 8.15.0 Version 8.15.0 of the agent confirms compatibility with Ruby 3.2.0, adds instrumentation for concurrent-ruby, and confirms Sinatra 3 compatibility with Padrino 0.15.2. It also enables batching and compression for Infinite Tracing. diff --git a/lib/new_relic/agent/configuration/default_source.rb b/lib/new_relic/agent/configuration/default_source.rb index 7af16babb4..3162738676 100644 --- a/lib/new_relic/agent/configuration/default_source.rb +++ b/lib/new_relic/agent/configuration/default_source.rb @@ -1137,7 +1137,6 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil) :default => false, :public => true, :type => Boolean, - :dynamic_name => true, :allowed_from_server => false, :description => 'If `true`, disables Action Cable instrumentation.' }, @@ -1145,17 +1144,22 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil) :default => false, :public => true, :type => Boolean, - :dynamic_name => true, :allowed_from_server => false, - :description => 'If `true`, disables ActiveJob instrumentation.' + :description => 'If `true`, disables Active Job instrumentation.' }, :disable_active_storage => { :default => false, :public => true, :type => Boolean, - :dynamic_name => true, :allowed_from_server => false, - :description => 'If `true`, disables ActiveStorage instrumentation.' + :description => 'If `true`, disables Active Storage instrumentation.' + }, + :disable_active_support => { + :default => false, + :public => true, + :type => Boolean, + :allowed_from_server => false, + :description => 'If `true`, disables Active Support instrumentation.' }, :disable_activerecord_instrumentation => { :default => value_of(:skip_ar_instrumentation), @@ -1163,7 +1167,7 @@ def self.enforce_fallback(allowed_values: nil, fallback: nil) :public => true, :type => Boolean, :allowed_from_server => false, - :description => 'If `true`, disables active record instrumentation.' + :description => 'If `true`, disables Active Record instrumentation.' }, :disable_active_record_notifications => { :default => false, diff --git a/lib/new_relic/agent/instrumentation/active_support.rb b/lib/new_relic/agent/instrumentation/active_support.rb index 497a0ca387..ef797896bf 100644 --- a/lib/new_relic/agent/instrumentation/active_support.rb +++ b/lib/new_relic/agent/instrumentation/active_support.rb @@ -2,11 +2,22 @@ # See https://github.com/newrelic/newrelic-ruby-agent/blob/main/LICENSE for complete details. # frozen_string_literal: true -# This is a helper file that will allow apps using ActiveSupport without Rails -# to still leverage all ActiveSupport based instrumentation functionality -# offered by the agent that would otherwise be gated by the detection of Rails. +require 'new_relic/agent/instrumentation/active_support_subscriber' -# ActiveSupport notifications custom events -if !defined?(Rails) && defined?(ActiveSupport::Notifications) && defined?(ActiveSupport::IsolatedExecutionState) - require_relative 'rails_notifications/custom_events' +DependencyDetection.defer do + named :active_support + + depends_on do + defined?(ActiveSupport) && + !NewRelic::Agent::Instrumentation::ActiveSupportSubscriber.subscribed? + end + + executes do + NewRelic::Agent.logger.info('Installing ActiveSupport instrumentation') + end + + executes do + ActiveSupport::Notifications.subscribe(/\.active_support$/, + NewRelic::Agent::Instrumentation::ActiveSupportSubscriber.new) + end end diff --git a/lib/new_relic/agent/instrumentation/active_support_subscriber.rb b/lib/new_relic/agent/instrumentation/active_support_subscriber.rb new file mode 100644 index 0000000000..faccad89bd --- /dev/null +++ b/lib/new_relic/agent/instrumentation/active_support_subscriber.rb @@ -0,0 +1,74 @@ +# 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 ActiveSupportSubscriber < NotificationsSubscriber + def start(name, id, payload) + return unless state.is_execution_traced? + + start_segment(name, id, payload) + rescue => e + log_notification_error(e, name, 'start') + end + + def finish(name, id, payload) + return unless state.is_execution_traced? + + finish_segment(id, payload) + rescue => e + log_notification_error(e, name, 'finish') + end + + def start_segment(name, id, payload) + segment = Tracer.start_segment(name: metric_name(name, payload)) + + add_segment_params(segment, payload) + push_segment(id, segment) + end + + def add_segment_params(segment, payload) + segment.params[:key] = payload[:key] + segment.params[:store] = payload[:store] + segment.params[:hit] = payload[:hit] if payload.key?(:hit) + segment.params[:super_operation] = payload[:super_operation] if payload.key?(:super_operation) + 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) + store = payload[:store] + method = method_from_name(name) + "Ruby/ActiveSupport/#{store}/#{method}" + end + + PATTERN = /\Acache_([^\.]*)\.active_support\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/lib/new_relic/agent/instrumentation/custom_events.rb b/lib/new_relic/agent/instrumentation/custom_events.rb new file mode 100644 index 0000000000..497a0ca387 --- /dev/null +++ b/lib/new_relic/agent/instrumentation/custom_events.rb @@ -0,0 +1,12 @@ +# 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 + +# This is a helper file that will allow apps using ActiveSupport without Rails +# to still leverage all ActiveSupport based instrumentation functionality +# offered by the agent that would otherwise be gated by the detection of Rails. + +# ActiveSupport notifications custom events +if !defined?(Rails) && defined?(ActiveSupport::Notifications) && defined?(ActiveSupport::IsolatedExecutionState) + require_relative 'rails_notifications/custom_events' +end diff --git a/newrelic.yml b/newrelic.yml index cf317d03f5..1187999266 100644 --- a/newrelic.yml +++ b/newrelic.yml @@ -175,6 +175,9 @@ common: &default_settings # If true, disables Active Storage instrumentation. # disable_active_storage: false + # If true, disables Active Support instrumentation. + # disable_active_support: false + # If true, disables Active Job instrumentation. # disable_activejob: false diff --git a/test/new_relic/agent/instrumentation/active_support_subscriber_test.rb b/test/new_relic/agent/instrumentation/active_support_subscriber_test.rb new file mode 100644 index 0000000000..c619d4eec9 --- /dev/null +++ b/test/new_relic/agent/instrumentation/active_support_subscriber_test.rb @@ -0,0 +1,12 @@ +# 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_support_subscriber' + +if defined?(ActiveSupport) + require_relative 'rails/active_support_subscriber' +else + puts "Skipping tests in #{__FILE__} because Active Support is unavailable" +end diff --git a/test/new_relic/agent/instrumentation/rails/active_support_subscriber.rb b/test/new_relic/agent/instrumentation/rails/active_support_subscriber.rb new file mode 100644 index 0000000000..24446f2fef --- /dev/null +++ b/test/new_relic/agent/instrumentation/rails/active_support_subscriber.rb @@ -0,0 +1,231 @@ +# 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' + +module NewRelic + module Agent + module Instrumentation + class ActiveSupportSubscriberTest < Minitest::Test + DEFAULT_STORE = 'MemCacheStore' + METRIC_PREFIX = 'Ruby/ActiveSupport/' + DEFAULT_PARAMS = {key: fake_guid(32), store: DEFAULT_STORE} + DEFAULT_EVENT = 'cache_read.active_support' + + def setup + nr_freeze_process_time + @subscriber = ActiveSupportSubscriber.new + @id = fake_guid(32) + + NewRelic::Agent.drop_buffered_data + end + + def teardown + NewRelic::Agent.drop_buffered_data + end + + def test_start_when_not_traced + @subscriber.state.stub :is_execution_traced?, false do + in_transaction do |txn| + @subscriber.start(DEFAULT_EVENT, @id, {}) + + assert_empty txn.segments + end + end + end + + def test_finish_when_not_traced + @subscriber.state.stub :is_execution_traced?, false do + in_transaction do |txn| + @subscriber.finish(DEFAULT_EVENT, @id, {}) + + assert_empty txn.segments + end + end + end + + def test_metrics_recorded_for_known_methods + method_name_mapping = { + "cache_read.active_support" => "read".freeze, + "cache_generate.active_support" => "generate".freeze, + "cache_fetch_hit.active_support" => "fetch_hit".freeze, + "cache_write.active_support" => "write".freeze, + "cache_delete.active_support" => "delete".freeze, + "cache_exist?.active_support" => "exist?".freeze + } + + in_transaction('test') do + method_name_mapping.keys.each do |event_name| + generate_event(event_name) + end + end + + method_name_mapping.values.each do |method_name| + assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/#{method_name}" + end + end + + def test_metric_recorded_for_new_event_names + in_transaction('test') do + generate_event('cache_new_method.active_support') + end + + assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/new_method" + end + + def test_failsafe_if_event_does_not_match_expected_pattern + in_transaction('test') do + generate_event('charcuterie_build_a_board_workshop') + end + + assert_metrics_recorded "#{METRIC_PREFIX}#{DEFAULT_STORE}/unknown" + end + + def test_key_recorded_as_attribute_on_traces + key = 'blades' + txn = in_transaction('test') do + generate_event('cache_read.active_support', key: key, hit: false) + end + + trace = last_transaction_trace + tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read") + + assert_equal key, tt_node.params[:key] + end + + def test_hit_recorded_as_attribute_on_traces + txn = in_transaction('test') do + generate_event('cache_read.active_support', DEFAULT_PARAMS.merge(hit: false)) + end + + trace = last_transaction_trace + tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read") + + puts txn.segments.last.inspect + + assert tt_node.params.key?(:hit) + refute tt_node.params[:hit] + end + + def test_super_operation_recorded_as_attribute_on_traces + txn = in_transaction('test') do + generate_event('cache_read.active_support', DEFAULT_PARAMS.merge(super_operation: nil)) + end + + trace = last_transaction_trace + tt_node = find_node_with_name(trace, "#{METRIC_PREFIX}#{DEFAULT_STORE}/read") + + puts txn.segments.last.inspect + + assert tt_node.params.key?(:super_operation) + refute tt_node.params[:super_operation] + end + + def test_segment_created + in_transaction('test') do + txn = NewRelic::Agent::Tracer.current_transaction + + assert_equal 1, txn.segments.size + + generate_event('cache_write.active_support', key: 'blade') + + assert_equal 2, txn.segments.size + assert_equal "#{METRIC_PREFIX}#{DEFAULT_STORE}/write", txn.segments.last.name + assert_predicate txn.segments.last, :finished?, "Segment #{txn.segments.last.name} was never finished. " + end + end + + def test_records_span_level_error + exception_class = StandardError + exception_msg = 'Natural 1' + exception = exception_class.new(msg = exception_msg) + # :exception_object was added in Rails 5 and above + params = {:exception_object => exception, :exception => [exception_class.name, exception_msg]} + + txn = nil + + in_transaction do |test_txn| + txn = test_txn + generate_event('cache_fetch_hit.active_support', params) + end + + assert_segment_noticed_error txn, /fetch/i, exception_class.name, /Natural 1/i + end + + def test_pop_segment_returns_false + @subscriber.stub :pop_segment, nil do + txn = in_transaction do |txn| + @subscriber.finish(DEFAULT_EVENT, @id, {}) + end + + assert txn.segments.none? { |s| s.name.include?('ActiveSupport') } + end + end + + def test_start_logs_notification_error + 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(DEFAULT_EVENT, @id, {}) + end + + assert_equal 1, txn.segments.size + end + end + logger.verify + end + + def test_finish_logs_notification_error + 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 :finish_segment, -> { raise 'kaboom' } do + @subscriber.finish(DEFAULT_EVENT, @id, {}) + end + + assert_equal 1, txn.segments.size + end + end + logger.verify + end + + def test_an_actual_active_storage_cache_write + unless defined?(ActiveSupport::VERSION::MAJOR) && ActiveSupport::VERSION::MAJOR >= 5 + skip 'Test restricted to Active Support v5+' + end + + in_transaction do |txn| + store = ActiveSupport::Cache::MemoryStore + key = 'city' + store.new.write(key, 'Walla Walla') + segment = txn.segments.last + + assert_equal 2, txn.segments.size + assert_equal segment.name, "Ruby/ActiveSupport/#{store}/write" + assert_equal key, segment.params[:key] + assert_equal store.to_s, segment.params[:store] + end + end + + private + + def generate_event(event_name, attributes = {}) + payload = DEFAULT_PARAMS.merge(attributes) + @subscriber.start(event_name, @id, payload) + yield if block_given? + @subscriber.finish(event_name, @id, payload) + end + end + end + end +end