Skip to content

Perf: instrument /search request path with New Relic method tracers#243

Merged
mdorf merged 4 commits into
developfrom
perf/search-newrelic-tracers
Jul 22, 2026
Merged

Perf: instrument /search request path with New Relic method tracers#243
mdorf merged 4 commits into
developfrom
perf/search-newrelic-tracers

Conversation

@mdorf

@mdorf mdorf commented Jul 22, 2026

Copy link
Copy Markdown
Member

Summary

GET /search is the highest externally consumed endpoint and averages ~890 ms. New Relic attributes 92.9% of that (~830 ms) to a single opaque controller segment; all I/O combined is under 60 ms per request (Redis ~44 ms, Solr ~10 ms, AllegroGraph 0.02 calls/request). Production thread profiling cannot see inside the block either (workers are ~98% idle between requests, so a 5-minute sample catches almost no in-request frames).

This PR closes that observability gap with twelve permanent method tracers plus one custom transaction attribute, registered from a declarative registry so future endpoints are one-line additions. After deploy, transaction traces and the breakdown table show named Custom/* segments instead of one opaque block, naming the specific method responsible for the time.

Evidence motivating this (last 24 h, 137,960 requests)

Band Count Avg duration All I/O combined
< 2 s 136,186 (98.7%) 870 ms ~55 ms
2 to 5 s 1,761 (1.3%) 2,377 ms ~195 ms
> 5 s 13 10,763 ms ~11,400 ms (AllegroGraph query storms on cache miss)

The dominant cost for 98.7% of traffic is in-process Ruby compute, not I/O. The rare > 5 s outliers are triple-store storms (separate, low-priority issue).

What is instrumented

New file config/newrelic_method_tracers.rb (declarative registry, loaded from app.rb after init):

GET /search pipeline

  • SearchHelper#process_search: whole pipeline; its self-time isolates the loop that builds read-only LinkedData::Models::Class objects from Solr documents
  • SearchHelper#get_term_search_query: Solr query construction
  • SearchHelper#add_matched_fields, SearchHelper#filter_attrs_by_language: highlight mapping and language filtering (the latter runs once per returned document, ~50/request; flagged in a comment as the one removal candidate if traces get noisy)
  • LinkedData::Models::Class.search: Solr call including Ruby-side response parsing

GET /ontologies/{ontology}/classes/{cls}/tree pipeline (slowest transaction by average duration, 1.61 s; known future tuning target)

  • LinkedData::Models::Class#tree, #tree_sorted, #paths_to_root (defined in an ontologies_linked_data concern, traced from here without touching that repo)

App-wide (every endpoint benefits)

  • ApplicationHelper#restricted_ontologies: loads the full ontology access list (prime suspect for /search)
  • ApplicationHelper#reply: access control, slice/user filtering, serialization entry
  • LinkedData::Serializer.build_response / .serialize: hypermedia link and JSON generation

SearchHelper#process_search 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:

SELECT average(duration) FROM Transaction WHERE name LIKE '%GET /search' FACET search_scoped

Permanent, not temporary

These follow standard New Relic custom instrumentation practice. Per-call overhead is microseconds against an 870 ms transaction. With the agent disabled (development/test) they are no-ops. No logic, query, or response-format changes.

Kill switch: NEWRELIC_CUSTOM_TRACERS=off (plus restart) skips all registration, to rule instrumentation out while debugging.

Test plan

  • New: test/helpers/test_newrelic_method_tracers.rb iterates the registry and asserts every entry is wrapped by newrelic_rpm; fails if a traced method is renamed or registration silently no-ops. Registry-driven, so future entries are covered automatically.
  • App boots in test env with all tracers active
  • test/controllers/test_search_controller.rb: 13 tests, 147 assertions, 0 failures against the local backend stack
  • test/controllers/test_classes_controller.rb (exercises /tree): 20 tests, 4,194 assertions, 0 failures

mdorf added 4 commits July 22, 2026 13:44
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.
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.
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.
@codecov-commenter

codecov-commenter commented Jul 22, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 78.60%. Comparing base (32d7a83) to head (9455366).

Additional details and impacted files
@@             Coverage Diff             @@
##           develop     #243      +/-   ##
===========================================
+ Coverage    78.59%   78.60%   +0.01%     
===========================================
  Files           67       67              
  Lines         3752     3754       +2     
===========================================
+ Hits          2949     2951       +2     
  Misses         803      803              
Flag Coverage Δ
ag 78.60% <100.00%> (+0.01%) ⬆️
fs 78.60% <100.00%> (+0.01%) ⬆️
gd 78.60% <100.00%> (+0.01%) ⬆️
unittests 78.60% <100.00%> (+0.01%) ⬆️
vo 78.60% <100.00%> (+0.01%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
  • 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

@mdorf
mdorf merged commit c5d0f16 into develop Jul 22, 2026
10 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants