GET /search: reduce response time (~830 ms of ~890 ms average is in application code)

[mdorf]

Problem

GET /search is the highest externally consumed endpoint in BioPortal (~138K requests/day, ~96 rpm average). It averages ~890 ms (median 848 ms, p95 1.34 s, p99 2.19 s, Apdex 0.5).

New Relic segment data shows the time is not spent in I/O: Solr answers in ~10 ms (~1% of transaction time), Redis adds ~44 ms across ~15 round trips, and the triple store is not called at all on ~98% of requests. Roughly 830 ms per request is in-process Ruby compute, previously invisible as a single opaque controller segment.

Originally flagged by @alexskr in Slack: the Solr server response is fast, but a 1-second average response should be investigated to see where the time goes.

Evidence so far

Duration segmentation over 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 SPARQL cache miss; rare, tracked separately)

PR #243 added method tracers that decompose the opaque segment. A local verification run (staging backends) attributes ~86% of the search pipeline to restricted_ontologies (helpers/application_helper.rb): on every site-wide search it loads all ~1,200 ontologies as goo model objects with a heavyweight attribute set, filters the full set (slice, user, ACL), then keeps only the acronyms to build the Solr filter query. The output is identical between requests for anonymous no-slice traffic and changes only when ontologies or ACLs change. Production tracer data (post v7.4.3 deploy) will confirm the share at scale.

Candidate improvements (to be validated against prod tracer data)

1. Slim the site-wide attribute load to acronym + access-control attributes (the ontology-scoped branch already does this).
2. Cache the computed accessible-acronym list (keyed by anonymous/slice/user, short TTL or invalidated on ontology/ACL change) instead of recomputing per request.
3. Avoid enumerating ~1,200 acronyms in the Solr fq for unrestricted traffic (e.g. exclude the small private set instead).
4. Batch the ~15 sequential Redis round trips (~44 ms, second-order).

Expected impact if the restricted_ontologies share holds in prod: average response time roughly halved, with the 2 to 5 s band compressed correspondingly.

Acceptance criteria

• Production tracer data identifies the dominant segment and the fix targets it
• Measurable before/after improvement in /search average and p95 from the same New Relic segments
• No behavior change to search results, access control, or response format

Related

• BioPortal search incorrectly ranks results #230 / PR Fix: incorrect search result rankings #232 (search ranking, prior work on this endpoint)
• PR Perf: instrument /search request path with New Relic method tracers #243 (instrumentation that enables this work, deployed in v7.4.3)

[mdorf]

Production baseline from the v7.4.3 tracers (first 18 h, ~81,700 /search requests)

Segment breakdown (avg per call, from Span data)

Segment	Avg
process_search (whole pipeline)	899 ms
get_term_search_query	878 ms
restricted_ontologies	876 ms (~97% of pipeline)
Class.search (Solr incl. parse)	15.6 ms
reply (serialization entry)	32.6 ms
Serializer.serialize	23.7 ms
filter_attrs_by_language	0.1 ms per doc

The local estimate (~86%) understated it: in production restricted_ontologies is ~97% of search pipeline time.

The search_scoped split overturned an assumption

	Count	Share	Avg
scoped (ontologies= given)	80,022	98%	962 ms
site-wide	1,705	2%	878 ms

Production traffic is almost entirely scoped, and scoped is just as slow. Root cause: the scoped path (ontology_objects_from_params, helpers/application_helper.rb:368-372) loads all ~1,200 ontologies with full goo_attrs_to_load attributes and then selects the requested ones in Ruby:

all_onts = LinkedData::Models::Ontology.where.include(LinkedData::Models::Ontology.goo_attrs_to_load).to_a
all_onts.select { |o| ontologies.include?(o.id.to_s) }

So both branches of restricted_ontologies reduce to the same load-everything call, which explains the near-identical averages. This refines candidate fix 2: the cache (or slimmed load) must sit under both paths, e.g. at the shared load-all-ontologies call, not only the site-wide branch. The naive_expiring_cache pattern already used by ontology_uri_acronym_map in the same file is a natural precedent.

Bonus: /tree segments (same deploy)

Class#tree averages 723 ms and paths_to_root 35 ms, so the tree endpoint's cost is concentrated inside tree itself. Useful starting point for the planned /tree tuning session.

Caveat: span events are sampled by the agent, so call counts above are sample counts; averages are representative.

This is the pre-fix baseline. Improvement should be measured against these same segments.

[mdorf]

Closing numbers: production, first 18 h after the v7.4.4 deploy (PR #245)

~66,300 /search requests measured via the #243 tracer segments (same instruments as the baseline above).

Metric	Baseline	Now	Δ
/search average (all traffic)	~960 ms	102 ms	−89%
Scoped search average (98% of traffic)	962 ms	98 ms	−90%
Scoped search median	883 ms	42 ms	−95%
Scoped search p95	1,391 ms	797 ms	−43%
restricted_ontologies segment	876 ms	137 ms	−84%
Solr (Class.search)	~16 ms	~18 ms	unchanged, as expected

Bonus from the shared-layer fix scope: annotator transactions dropped from 1,011 ms to 162 ms (−84%) with no annotator-specific changes; recommender/mappings/analytics ride the same helper.

Cache internals match the design exactly: misses (load_ontologies) cost 895 ms, i.e. the old per-request price paid once per 300 s per worker; the measured ~7% miss rate matches the per-worker request rate against the TTL. The remaining p95 tail is mostly those amortized misses; if further tail reduction is ever wanted, raising ontology_list_cache_ttl or adding refresh-ahead are the knobs (longer staleness in trade).

All acceptance criteria are met: the dominant segment was identified and targeted, the improvement is measured from the same production segments, and the parity suites plus staging checks showed no behavior change. Recommend closing this issue; the OTel follow-up lives in #246 and the /tree investigation remains a separate future effort.