From 3ae5578f1c21eb093087355673f11cc2e54ba1e8 Mon Sep 17 00:00:00 2001 From: Michael Dorf Date: Wed, 22 Jul 2026 13:44:09 -0700 Subject: [PATCH 1/4] Add New Relic method tracers for /search diagnostics GET /search averages ~890 ms, of which ~830 ms (92.9%) appears as a single opaque controller segment in New Relic; all I/O combined (Redis, Solr, AllegroGraph) accounts for under 60 ms. These tracers split the opaque block into named Custom/* segments covering query construction, the ontology access list load, per-document model building, and response serialization, so transaction traces name the method responsible for the time. Also records a search_scoped transaction attribute (the agent strips query strings from request.uri), enabling NRQL comparison of ontology-scoped vs site-wide searches. No behavior change: tracers are no-ops when the agent is disabled. --- app.rb | 3 ++ config/newrelic_method_tracers.rb | 49 +++++++++++++++++++++++++++++++ helpers/search_helper.rb | 6 ++++ 3 files changed, 58 insertions(+) create mode 100644 config/newrelic_method_tracers.rb diff --git a/app.rb b/app.rb index f57bb0b09..6db21442a 100644 --- a/app.rb +++ b/app.rb @@ -183,6 +183,9 @@ # Initialize the app require_relative 'init' +# Custom method tracers (must load after init so traced methods exist) +require_relative 'config/newrelic_method_tracers' + # Enter console mode if settings.environment == :console require 'rack/test' diff --git a/config/newrelic_method_tracers.rb b/config/newrelic_method_tracers.rb new file mode 100644 index 000000000..4e1b815d5 --- /dev/null +++ b/config/newrelic_method_tracers.rb @@ -0,0 +1,49 @@ +# Custom New Relic method tracers for the /search request path. +# +# The GET /search transaction spends >90% of its time in application code +# that the agent reports as a single opaque "Sinatra::Application#GET +# (unknown)" segment (~830 ms of the ~890 ms average). These tracers split +# that block into named Custom/* child segments so transaction traces and +# the breakdown table show where the time actually goes. +# +# Must be loaded after init.rb so all traced methods are already defined. +# When the agent is disabled (development/test), the tracers are no-ops. +require 'new_relic/agent/method_tracer' + +module Sinatra + module Helpers + module SearchHelper + include ::NewRelic::Agent::MethodTracer + + add_method_tracer :process_search, 'Custom/SearchHelper/process_search' + add_method_tracer :get_term_search_query, 'Custom/SearchHelper/get_term_search_query' + add_method_tracer :add_matched_fields, 'Custom/SearchHelper/add_matched_fields' + # Called once per returned document (default pagesize 50). + add_method_tracer :filter_attrs_by_language, 'Custom/SearchHelper/filter_attrs_by_language' + end + + module ApplicationHelper + include ::NewRelic::Agent::MethodTracer + + # Site-wide searches load every ontology here before querying Solr. + add_method_tracer :restricted_ontologies, 'Custom/ApplicationHelper/restricted_ontologies' + add_method_tracer :reply, 'Custom/ApplicationHelper/reply' + end + end +end + +# Serialization of the result page (hypermedia links + JSON generation). +LinkedData::Serializer.singleton_class.class_eval do + include ::NewRelic::Agent::MethodTracer + + add_method_tracer :build_response, 'Custom/LinkedData::Serializer/build_response' + add_method_tracer :serialize, 'Custom/LinkedData::Serializer/serialize' +end + +# Solr query execution + response parsing (the HTTP call itself is already +# instrumented as an External segment; this segment adds the parse cost). +LinkedData::Models::Class.singleton_class.class_eval do + include ::NewRelic::Agent::MethodTracer + + add_method_tracer :search, 'Custom/LinkedData::Models::Class/search' +end diff --git a/helpers/search_helper.rb b/helpers/search_helper.rb index c7420eca2..81c59c0e1 100644 --- a/helpers/search_helper.rb +++ b/helpers/search_helper.rb @@ -560,6 +560,12 @@ def process_search(params = nil) params.delete('query') text = params["q"] + # The agent strips query strings from request.uri, so record whether + # this search is ontology-scoped as a queryable transaction attribute + if defined?(::NewRelic::Agent) + ::NewRelic::Agent.add_custom_attributes(search_scoped: !params[ONTOLOGIES_PARAM].to_s.empty?) + end + query = get_term_search_query(text, params) # puts "Edismax query: #{query}, params: #{params}" set_page_params(params) From 065b09444b08bbfbc0f04c784932c6db86846405 Mon Sep 17 00:00:00 2001 From: Michael Dorf Date: Wed, 22 Jul 2026 13:50:11 -0700 Subject: [PATCH 2/4] Add regression test for /search method tracer registration add_method_tracer silently no-ops when a target method is missing, so a rename or move could drop instrumentation without failing any test. Assert all nine traced methods are wrapped and that each wrapper is defined inside the newrelic_rpm gem. --- test/helpers/test_newrelic_method_tracers.rb | 53 ++++++++++++++++++++ 1 file changed, 53 insertions(+) create mode 100644 test/helpers/test_newrelic_method_tracers.rb diff --git a/test/helpers/test_newrelic_method_tracers.rb b/test/helpers/test_newrelic_method_tracers.rb new file mode 100644 index 000000000..390c2e37b --- /dev/null +++ b/test/helpers/test_newrelic_method_tracers.rb @@ -0,0 +1,53 @@ +require_relative '../test_case_helpers' + +# Guards the custom New Relic instrumentation of the /search request path +# (config/newrelic_method_tracers.rb). If a traced method is renamed or +# moved, add_method_tracer logs a warning and silently no-ops, so without +# these assertions the instrumentation could vanish unnoticed while the +# rest of the suite stays green. +class TestNewRelicMethodTracers < TestCaseHelpers + + TRACED_INSTANCE_METHODS = { + Sinatra::Helpers::SearchHelper => %i[process_search get_term_search_query + add_matched_fields filter_attrs_by_language], + Sinatra::Helpers::ApplicationHelper => %i[restricted_ontologies reply] + }.freeze + + TRACED_CLASS_METHODS = { + LinkedData::Serializer => %i[build_response serialize], + LinkedData::Models::Class => %i[search] + }.freeze + + def test_instance_method_tracers_registered + TRACED_INSTANCE_METHODS.each do |mod, methods| + methods.each do |method_name| + unbound = mod.instance_method(method_name) + refute_equal mod, unbound.owner, + "#{mod}##{method_name} is not wrapped by a method tracer" + assert_wrapped_by_newrelic(unbound, "#{mod}##{method_name}") + end + end + end + + def test_class_method_tracers_registered + TRACED_CLASS_METHODS.each do |cls, methods| + methods.each do |method_name| + unbound = cls.singleton_class.instance_method(method_name) + refute_equal cls.singleton_class, unbound.owner, + "#{cls}.#{method_name} is not wrapped by a method tracer" + assert_wrapped_by_newrelic(unbound, "#{cls}.#{method_name}") + end + end + end + + private + + # The tracer wrapper is defined inside the newrelic_rpm gem, so the + # wrapped method's source_location must point there. This distinguishes + # a genuine tracer from any other module that happens to prepend. + def assert_wrapped_by_newrelic(unbound_method, label) + source_file = unbound_method.source_location&.first.to_s + assert_match(/newrelic/, source_file, + "#{label} is wrapped, but not by newrelic_rpm (source: #{source_file})") + end +end From 7b46667100dfdb59be80e9694bd7ba2694d5f271 Mon Sep 17 00:00:00 2001 From: Michael Dorf Date: Wed, 22 Jul 2026 13:57:13 -0700 Subject: [PATCH 3/4] Add NEWRELIC_CUSTOM_TRACERS=off kill switch for custom tracers --- config/newrelic_method_tracers.rb | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/config/newrelic_method_tracers.rb b/config/newrelic_method_tracers.rb index 4e1b815d5..70577880f 100644 --- a/config/newrelic_method_tracers.rb +++ b/config/newrelic_method_tracers.rb @@ -8,6 +8,12 @@ # # Must be loaded after init.rb so all traced methods are already defined. # When the agent is disabled (development/test), the tracers are no-ops. +# +# Kill switch: set NEWRELIC_CUSTOM_TRACERS=off (and restart) to skip +# registration entirely, e.g. to rule instrumentation out while +# debugging. Requires a process restart to take effect either way. +return if ENV['NEWRELIC_CUSTOM_TRACERS'] == 'off' + require 'new_relic/agent/method_tracer' module Sinatra From 94553668a61c24f75efe382ad624c85f073dde51 Mon Sep 17 00:00:00 2001 From: Michael Dorf Date: Wed, 22 Jul 2026 14:03:58 -0700 Subject: [PATCH 4/4] Convert tracers to a registry and instrument the /tree endpoint Restructure config/newrelic_method_tracers.rb into a declarative registry so instrumenting another endpoint is a one-line addition; the regression test iterates the same registry, covering new entries automatically. Add tracers for the tree request path (LinkedData::Models::Class#tree, tree_sorted, paths_to_root, defined in an ontologies_linked_data concern but traceable from here), since GET .../classes/{cls}/tree is the slowest transaction by average duration (1.61 s) and a known future tuning target. --- config/newrelic_method_tracers.rb | 82 +++++++++++--------- test/helpers/test_newrelic_method_tracers.rb | 42 ++++------ 2 files changed, 63 insertions(+), 61 deletions(-) diff --git a/config/newrelic_method_tracers.rb b/config/newrelic_method_tracers.rb index 70577880f..81638162a 100644 --- a/config/newrelic_method_tracers.rb +++ b/config/newrelic_method_tracers.rb @@ -1,10 +1,14 @@ -# Custom New Relic method tracers for the /search request path. +# Custom New Relic method tracers for hot request paths. # -# The GET /search transaction spends >90% of its time in application code -# that the agent reports as a single opaque "Sinatra::Application#GET -# (unknown)" segment (~830 ms of the ~890 ms average). These tracers split -# that block into named Custom/* child segments so transaction traces and -# the breakdown table show where the time actually goes. +# High-traffic transactions (GET /search, GET .../classes/{cls}/tree) +# spend most of their time in application code that the agent reports as +# a single opaque "Sinatra::Application#GET (unknown)" segment. These +# tracers split that block into named Custom/* child segments so +# transaction traces and the breakdown table show where the time goes. +# +# To instrument another endpoint, add its module/class and methods to the +# registry below; test/helpers/test_newrelic_method_tracers.rb consumes +# the same registry, so new entries are covered automatically. # # Must be loaded after init.rb so all traced methods are already defined. # When the agent is disabled (development/test), the tracers are no-ops. @@ -12,44 +16,50 @@ # Kill switch: set NEWRELIC_CUSTOM_TRACERS=off (and restart) to skip # registration entirely, e.g. to rule instrumentation out while # debugging. Requires a process restart to take effect either way. -return if ENV['NEWRELIC_CUSTOM_TRACERS'] == 'off' - -require 'new_relic/agent/method_tracer' +module NewRelicMethodTracers + # Instance methods, keyed by module/class name. Methods inherited from + # concerns or mixins (e.g. the tree methods, defined in an + # ontologies_linked_data concern) can be traced here without touching + # the defining repo. + INSTANCE_METHODS = { + # GET /search pipeline + 'Sinatra::Helpers::SearchHelper' => %i[process_search get_term_search_query + add_matched_fields filter_attrs_by_language], + # App-wide: ontology access list load + response serialization entry + 'Sinatra::Helpers::ApplicationHelper' => %i[restricted_ontologies reply], + # GET /ontologies/{ontology}/classes/{cls}/tree pipeline + 'LinkedData::Models::Class' => %i[tree tree_sorted paths_to_root] + }.freeze -module Sinatra - module Helpers - module SearchHelper - include ::NewRelic::Agent::MethodTracer + # Class (singleton) methods, keyed by class name. + CLASS_METHODS = { + # Hypermedia links + JSON generation for every API response + 'LinkedData::Serializer' => %i[build_response serialize], + # Solr query execution incl. Ruby-side response parsing (the HTTP + # call itself already appears as an External segment) + 'LinkedData::Models::Class' => %i[search] + }.freeze - add_method_tracer :process_search, 'Custom/SearchHelper/process_search' - add_method_tracer :get_term_search_query, 'Custom/SearchHelper/get_term_search_query' - add_method_tracer :add_matched_fields, 'Custom/SearchHelper/add_matched_fields' - # Called once per returned document (default pagesize 50). - add_method_tracer :filter_attrs_by_language, 'Custom/SearchHelper/filter_attrs_by_language' + def self.register + INSTANCE_METHODS.each do |const_name, methods| + install(Object.const_get(const_name), const_name, methods) end - module ApplicationHelper - include ::NewRelic::Agent::MethodTracer - - # Site-wide searches load every ontology here before querying Solr. - add_method_tracer :restricted_ontologies, 'Custom/ApplicationHelper/restricted_ontologies' - add_method_tracer :reply, 'Custom/ApplicationHelper/reply' + CLASS_METHODS.each do |const_name, methods| + install(Object.const_get(const_name).singleton_class, const_name, methods) end end -end -# Serialization of the result page (hypermedia links + JSON generation). -LinkedData::Serializer.singleton_class.class_eval do - include ::NewRelic::Agent::MethodTracer + def self.install(target, const_name, methods) + target.include(::NewRelic::Agent::MethodTracer) - add_method_tracer :build_response, 'Custom/LinkedData::Serializer/build_response' - add_method_tracer :serialize, 'Custom/LinkedData::Serializer/serialize' + methods.each do |method_name| + target.send(:add_method_tracer, method_name, "Custom/#{const_name}/#{method_name}") + end + end end -# Solr query execution + response parsing (the HTTP call itself is already -# instrumented as an External segment; this segment adds the parse cost). -LinkedData::Models::Class.singleton_class.class_eval do - include ::NewRelic::Agent::MethodTracer - - add_method_tracer :search, 'Custom/LinkedData::Models::Class/search' +unless ENV['NEWRELIC_CUSTOM_TRACERS'] == 'off' + require 'new_relic/agent/method_tracer' + NewRelicMethodTracers.register end diff --git a/test/helpers/test_newrelic_method_tracers.rb b/test/helpers/test_newrelic_method_tracers.rb index 390c2e37b..aab0ed4f1 100644 --- a/test/helpers/test_newrelic_method_tracers.rb +++ b/test/helpers/test_newrelic_method_tracers.rb @@ -1,41 +1,32 @@ require_relative '../test_case_helpers' -# Guards the custom New Relic instrumentation of the /search request path -# (config/newrelic_method_tracers.rb). If a traced method is renamed or +# Guards the custom New Relic instrumentation registered by +# config/newrelic_method_tracers.rb. If a traced method is renamed or # moved, add_method_tracer logs a warning and silently no-ops, so without # these assertions the instrumentation could vanish unnoticed while the # rest of the suite stays green. +# +# The tests iterate the registry itself, so entries added to +# NewRelicMethodTracers::INSTANCE_METHODS / CLASS_METHODS are covered +# automatically. class TestNewRelicMethodTracers < TestCaseHelpers - TRACED_INSTANCE_METHODS = { - Sinatra::Helpers::SearchHelper => %i[process_search get_term_search_query - add_matched_fields filter_attrs_by_language], - Sinatra::Helpers::ApplicationHelper => %i[restricted_ontologies reply] - }.freeze - - TRACED_CLASS_METHODS = { - LinkedData::Serializer => %i[build_response serialize], - LinkedData::Models::Class => %i[search] - }.freeze - def test_instance_method_tracers_registered - TRACED_INSTANCE_METHODS.each do |mod, methods| + NewRelicMethodTracers::INSTANCE_METHODS.each do |const_name, methods| + mod = Object.const_get(const_name) methods.each do |method_name| - unbound = mod.instance_method(method_name) - refute_equal mod, unbound.owner, - "#{mod}##{method_name} is not wrapped by a method tracer" - assert_wrapped_by_newrelic(unbound, "#{mod}##{method_name}") + assert_wrapped_by_newrelic(mod.instance_method(method_name), + "#{const_name}##{method_name}") end end end def test_class_method_tracers_registered - TRACED_CLASS_METHODS.each do |cls, methods| + NewRelicMethodTracers::CLASS_METHODS.each do |const_name, methods| + singleton = Object.const_get(const_name).singleton_class methods.each do |method_name| - unbound = cls.singleton_class.instance_method(method_name) - refute_equal cls.singleton_class, unbound.owner, - "#{cls}.#{method_name} is not wrapped by a method tracer" - assert_wrapped_by_newrelic(unbound, "#{cls}.#{method_name}") + assert_wrapped_by_newrelic(singleton.instance_method(method_name), + "#{const_name}.#{method_name}") end end end @@ -44,10 +35,11 @@ def test_class_method_tracers_registered # The tracer wrapper is defined inside the newrelic_rpm gem, so the # wrapped method's source_location must point there. This distinguishes - # a genuine tracer from any other module that happens to prepend. + # a genuine tracer from the untraced original (defined in this repo or + # its gems) and from any other module that happens to prepend. def assert_wrapped_by_newrelic(unbound_method, label) source_file = unbound_method.source_location&.first.to_s assert_match(/newrelic/, source_file, - "#{label} is wrapped, but not by newrelic_rpm (source: #{source_file})") + "#{label} is not wrapped by a newrelic_rpm method tracer (source: #{source_file})") end end