Add query-latency and Solr health metrics to /status, with a performance-diagnostics guide by gaurav · Pull Request #231 · NCATSTranslator/NameResolution

gaurav · 2025-12-18T21:55:52Z

Adds latency tracking and native Solr + host health metrics to /status, plus a diagnostics guide for reading them — a lightweight way to see how much strain a NameRes instance and its Solr backend are under, and to size the Solr pod. Originally motivated by #228.

Rebranched onto current main (was ~41 commits behind); /status core-name handling was reconciled with main's SOLR_CORE env-var + single-core fallback, so the hardcoded name_lookup_shard1_replica_n1 is gone.

`/status` — always on (no Solr round-trip)

recent_queries — rolling window (default 50000, RECENT_TIMES_COUNT) of recent /lookup timings: mean_time_ms, mean_solr_time_ms (Solr wait only), and end-to-end p50_ms/p95_ms/p99_ms. These measure the full round-trip the caller sees, so comparing them with Solr's own percentiles (below) localizes a latency tail to Solr vs. NameRes. Computed from local data, so they stay on the default path where monitoring can scrape them cheaply.
Slow-query logging — /lookup calls over SLOW_QUERY_THRESHOLD_MS (default 500) log at WARNING (SLOW QUERY: …) instead of INFO.

`/status?full=true` — `solr_metrics` (one `/admin/metrics` round-trip)

Gated so the default /status stays cheap for k8s liveness probes; holds a {"message": …} placeholder otherwise.

query_handler — /select request/error/timeout counts + Solr-side p50/p95/p99.
cache — both filterCache and queryResultCache (hitratio/lookups/hits/evictions/size). NameRes filters heavily (fq), so filterCache usually matters most.
jvm — heap used/max/pct, CPU load, and cumulative GC (gc_count/gc_time_ms).
host — available_processors, system load/CPU, and total_physical_mem_mb — the inputs for sizing the Solr pod's CPU/memory.

Also fixes two latent parse bugs found against a live Solr 9.10: the heap gauge comes back as flat dotted keys (memory.heap.used), not a nested object, so heap fields were always null; and errors/timeouts are meters, so the whole meter dict was emitted instead of a scalar count.

Documentation

documentation/Performance.md — diagnostics guide adapted from PR Release v1.5.2 with metrics #253 (which isn't being merged to main), rewritten to this PR's actual field shape: metric meanings, log interpretation, where Solr's logs go (incl. GC logs), and a CPU-vs-memory-vs-load decision tree. Cross-linked from API.md.
documentation/API.md — the full /status response documented.

Companion deployment changes (separate repo)

Performance.md's GC-log guidance assumes a companion change to the name-lookup Helm chart in translator-devops (not in this repo): route Solr's GC log to stdout (GC_LOG_OPTS=-Xlog:gc:stdout:time,uptime) so it reaches Grafana instead of an ephemeral file, add ephemeral-storage requests/limits for the Solr and web pods, and make the blocklist secret fail-fast. Those are deployed there; this PR only carries the app + docs.

Design notes

Query parameter ?full=true — matches the original v1.5.2 /status?full feature and issue Surface OS page-cache stats (Buffers/Cached) in /status?full=true #267 (and any frontend still calling the old deployment).
OS page cache (Solr node) intentionally not reported. Solr's JVM only exposes Linux MemFree (excludes page cache), and reading /proc/meminfo from the API pod would report the API node — misleading when the two aren't co-located. The proper path for Surface OS page-cache stats (Buffers/Cached) in /status?full=true #267 is a node-level exporter (node_exporter/Prometheus) on the Solr host.
Trimmed as clutter: host.free_physical_mem_mb (MemFree, near-zero on a healthy node), host.open/max_file_descriptors (irrelevant to sizing), and query_handler.p75_ms (replaced with p50_ms for symmetry). Kept cache.hits+lookups and gc_count+gc_time_ms — sampling their deltas gives recent rates the cumulative ratios can't.
Not ported from Release v1.5.2 with metrics #253: rate windows (QPS 10s/60s/300s, inter-arrival gaps) — those genuinely need per-query timestamps; host load + query_handler.requests cover "is it load?".

Testing

tests/test_status.py covers the recent_queries shape (incl. percentiles), ?full=true gating, and the query_handler/cache/jvm/host fields. Full suite green locally and on GitHub Actions.

Original design also landed in Release v1.5.2 with metrics #253 (into ci); this PR keeps the observability piece clean for main and picks up the durable value from Release v1.5.2 with metrics #253 (Performance.md, slow-query logging, filterCache), since that branch won't be merged.
Motivated by Add logging #228. The host/jvm/cache metrics are the inputs for deployment-tuning issues Reduce Solr JVM heap to leave room for OS page cache #265 (reduce JVM heap for page cache), Grow queryResultCache (size=512, 56% hit rate, 317K evictions) #266 (grow queryResultCache — closed), and Surface OS page-cache stats (Buffers/Cached) in /status?full=true #267 (surface OS page-cache stats — see the note above).

Copilot

Pull request overview

Adds lightweight in-process tracking of recent lookup durations to help estimate service strain, exposing this data via /status to support the logging/monitoring goals described in #228.

Changes:

Track recent lookup timings in a bounded in-memory deque.
Extend /status response to include recent query timing statistics and samples.
Refactor lookup logging to reuse computed timing values.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Copilot · 2026-04-07T16:43:41Z

    time_end = time.time_ns()
+    time_taken_ms = (time_end - time_start)/1_000_000
+    time_taken_ms_solr = (time_solr_end - time_solr_start)/1_000_000
+    recent_query_times.append(time_taken_ms)


The comment and variable name suggest you're tracking “Solr query time”, but the value appended is time_taken_ms (overall request time including non-Solr processing). This makes /status's recent_queries.mean_time_ms ambiguous/misleading. Either append time_taken_ms_solr (if you want Solr time) or rename the variables/keys to reflect total request timing (or expose both metrics separately).

Suggested change

recent_query_times.append(time_taken_ms)

recent_query_times.append(time_taken_ms_solr)

- Track Solr-only wait time in a separate deque so mean_solr_time_ms can be distinguished from total API time in /status - Pull query handler (requests/errors/timeouts/p75/p95/p99), cache (hitratio/evictions), and JVM (heap %, CPU load) from Solr's /admin/metrics API; fails gracefully with solr_metrics: null - Fix RECENT_TIMES_COUNT env var type cast (int) to prevent deque crash - Replace -1 sentinel with None for empty mean; remove verbose recent_times_ms list from response Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

- Combine two /admin/metrics calls into one (group=core&group=jvm), halving the round-trip overhead per /status request - Pin core key to name_lookup_shard1_replica_n1 instead of non- deterministic next() iteration over the metrics dict - Move raise_for_status() inside the async with block so all Solr I/O is co-located - Add test_status_shape and test_status_recent_queries_populated tests - Update API.md with recent_queries and solr_metrics response fields Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

…atus The Solr metrics round-trip is skipped unless the caller explicitly passes ?metrics=true. The solr_metrics key is omitted from the response entirely when not requested. Tests and API.md updated accordingly. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

Copilot

Pull request overview

Copilot reviewed 3 out of 3 changed files in this pull request and generated 4 comments.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

Adds some metrics for tracking performance on the Solr database: * Adds a `?full=true` mode to the /status endpoint which provides more detailed information from Solr, including memory/CPU information and cache information. * Maintains a "recent times" deque which is used to continuously report on recent queries and to inform people when query time is going up (reimplements part of PR #231). * Logs queries along with time taken for tracking performance in the long term (incorporates PR #230, which has been merged into branch `master` but not into branch `ci`). Also some unrelated changes: * Renames `reverse_lookup()` to `curie_lookup()` and `lookup_names_(get|post)` with `synonyms_(get|post)` for clarity. * Fixed a typo in data-loading/README.md.

# Conflicts: # api/server.py

- Use the single solr.core.* metrics registry instead of the hardcoded name_lookup_shard1_replica_n1, so metrics populate under the standalone name_lookup core (matches the SOLR_CORE handling already on main). - API.md: document the recent_queries.max field and correct the solr_metrics description (it holds a {message: ...} placeholder, not null, when metrics aren't requested or Solr's metrics API is unavailable). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

Adds the Solr host resource and GC signals needed to right-size the Solr pod's CPU/memory, all from the existing single /admin/metrics round-trip: - host: available_processors, system/process CPU load, total/free physical memory, file-descriptor counts. Solr mmaps its read-only index, so physical RAM beyond the heap is OS page cache — this is what sizing decisions hinge on. - jvm: gc_count and gc_time_ms (summed across whichever collectors run), a direct heap-pressure signal. Also fixes two latent parse bugs in the metrics block: - heap gauge is returned by Solr as flat dotted keys (memory.heap.used), not a nested object, so heap_used_mb/heap_max_mb/heap_used_pct were always null. Now handles both shapes. - errors/timeouts are meters ({count, meanRate, ...}), not scalars; report the cumulative count instead of dumping the whole meter dict. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

…=true - Bump RECENT_TIMES_COUNT default 1000 -> 50000 for a much longer rolling performance window (~a few MB per deque; still trivial). - Add api_node_memory: OS page-cache stats (buffers/cached/available/total) read from the API node's /proc/meminfo. Solr's JVM metrics can't report page cache (freePhysicalMemorySize is Linux MemFree, which excludes it), so this local read is the only page-cache signal available. It reflects the API node, which equals the Solr node only when co-located; null on non-Linux hosts. Addresses the intent of #267 within what this architecture can actually see. - Rename the extended-metrics query parameter from ?metrics=true to ?full=true, matching the original v1.5.2 /status?full feature and issue #267 (and any frontend still calling the old deployment). Now gates both solr_metrics and api_node_memory. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

Reading /proc/meminfo on the API node reports that node's memory, which is only the Solr node's when they are co-located — too easy to misread as Solr's page cache. Removed to avoid the confusion; the ?full=true rename and the 50000 recent-times window stay. True Solr-node page-cache visibility belongs in a node-level exporter (node_exporter/Prometheus) on the Solr host. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

Two small, high-value observability bits from the v1.5.2 metrics work that make the /status metrics actionable (and that documentation/Performance.md relies on): - Slow-query logging: /lookup queries exceeding SLOW_QUERY_THRESHOLD_MS (default 500) now log at WARNING ("SLOW QUERY: ...") instead of INFO, so they stand out. - filterCache: report both filterCache and queryResultCache under solr_metrics.cache, each with hitratio/lookups/hits/evictions/size. NameRes filters heavily by prefix/type/taxon (Solr fq), so filterCache is often the more important of the two. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

Ports the performance-diagnostics doc from the v1.5.2 branch (which is not being merged to main), rewritten to match this PR's actual /status?full=true field shape: recent_queries means, solr_metrics.query_handler percentiles, jvm heap/GC, host CPU/memory, and filterCache/queryResultCache. Covers metric meanings, log interpretation, a CPU-vs-memory-vs-load decision tree, and the env vars. Cross-linked from API.md. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

Percentiles (the valuable half of #253's app-side stats) turn out to need only the durations we already keep in recent_query_times — no timestamp/query_log redesign. Unlike Solr's query_handler percentiles, these measure the full round-trip the caller sees, so comparing the two localizes a latency tail to Solr vs. NameRes. They need no Solr round-trip, so they stay on the default /status path where monitoring can scrape them cheaply. - recent_queries: add p50_ms/p95_ms/p99_ms (end-to-end). - query_handler: replace p75_ms with p50_ms (Solr's median_ms) — p75 is the least informative percentile, and this makes both blocks symmetric p50/95/99. Removed as clutter: - host.free_physical_mem_mb — Solr's JVM reports Linux MemFree, which excludes page cache and so reads near-zero on a healthy node. Misleading, not useful. - host.open_file_descriptors / max_file_descriptors — a niche fd-exhaustion signal that says nothing about CPU/memory sizing. Kept deliberately: cache hits+lookups and gc_count+gc_time_ms look redundant with hitratio/mean pause, but sampling their deltas gives recent rates that the cumulative ratios cannot. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

The GC-pause guidance pointed at "Solr's GC logs" without saying where they are, which was misleading: the GC log is a JVM-level -Xlog sink that bypasses log4j2, and Solr's default writes it to /var/solr/logs/solr_gc.log -- a path that is not on the Solr PVC in our Helm chart (only /var/solr/data is mounted), so it is ephemeral and lost on the very restart that prompts you to read it. It also never reached stdout, so it was absent from Grafana. The chart now sets GC_LOG_OPTS="-Xlog:gc:stdout:time,uptime" so GC lines are collected alongside solr.log. Documents that, the bare-gc vs gc* verbosity tradeoff, the file-based fallback, and jvm.gc_count/gc_time_ms as the aggregate signal when logs aren't handy. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

The SLOW_QUERY_THRESHOLD_MS branch added with the /status metrics work had no coverage. Two tests pin both sides: with the threshold at 0 a lookup must log "SLOW QUERY" at WARNING, and with it very high it must not. Verified by mutation (forcing the branch to INFO fails the first test). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

- /status now also reports recent-query latency, and ?full=true adds Solr/JVM/host metrics; the entry still described only document counts. - List documentation/Performance.md. - Note that Solr's /admin/metrics encodes counters, timers/meters and JVM gauges differently. Guessing wrong yields a silent null rather than an error, which is how heap_used_mb and errors/timeouts both shipped broken in this branch before being caught against a live Solr. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

gaurav · 2026-07-27T09:06:56Z

TODO if this merges after #259: that PR adds an agent skill (skills/nameres/SKILL.md, also served at GET /llms.txt) with a "Which data am I querying?" section describing /status.

It deliberately documents only babel_version, nameres_version and the conflations, and does not describe the response shape — partly because this PR is in flight, and partly because ITRB CI (v1.5.2) already returns a third shape, nesting the Solr fields under "solr".

When this lands, /status gains recent_queries and solr_metrics, so that section is worth a look — mainly to decide whether an agent should be told the latency percentiles exist at all, or whether they are operator-facing only.

gaurav added 3 commits December 18, 2025 16:46

Added a "recent times" that allows us to track query times.

9227999

Improved name.

ddeb95d

Merge branch 'master' into track-recent-times

aa48597

gaurav added this to NameRes sprints Feb 20, 2026

github-project-automation Bot moved this to Backlog in NameRes sprints Feb 20, 2026

gaurav moved this from Backlog to In progress in NameRes sprints Apr 6, 2026

gaurav added 2 commits April 7, 2026 10:38

Merge branch 'master' into track-recent-times

e47524e

Cleaned up code.

e17e784

gaurav requested a review from Copilot April 7, 2026 16:40

Copilot started reviewing on behalf of gaurav April 7, 2026 16:41 View session

Copilot AI reviewed Apr 7, 2026

View reviewed changes

gaurav and others added 3 commits April 7, 2026 10:56

gaurav requested a review from Copilot April 7, 2026 17:04

Copilot started reviewing on behalf of gaurav April 7, 2026 17:05 View session

Copilot AI reviewed Apr 7, 2026

View reviewed changes

Comment thread api/server.py Outdated

Comment thread api/server.py Outdated

Comment thread api/server.py Outdated

Comment thread documentation/API.md

gaurav and others added 5 commits April 7, 2026 13:19

Update api/server.py

e094153

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

Cleaned up solr_metrics inclusion.

2e9bfa9

Dedup SOLR_CORE_NAME.

a4a1d1d

Fix typo.

e8a4a00

Attempt to reorganize and fix tests.

17c4107

gaurav self-assigned this Apr 7, 2026

Improved recent_queries output.

38677c3

gaurav marked this pull request as ready for review April 7, 2026 17:47

gaurav mentioned this pull request Apr 8, 2026

Release v1.5.2 with metrics #253

Merged

gaurav and others added 3 commits July 23, 2026 16:05

Merge remote-tracking branch 'origin/main' into track-recent-times

1361c04

# Conflicts: # api/server.py

gaurav changed the title ~~Track recent times~~ Track recent query times and expose Solr health metrics via /status Jul 23, 2026

gaurav and others added 6 commits July 23, 2026 16:27

gaurav changed the title ~~Track recent query times and expose Solr health metrics via /status~~ Add query-latency and Solr health metrics to /status, with a performance-diagnostics guide Jul 24, 2026

gaurav and others added 2 commits July 24, 2026 03:34

gaurav mentioned this pull request Jul 27, 2026

Improve NameRes documentation: Translator Guide, Babel data guide, and doc drift fixes #262

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Add query-latency and Solr health metrics to /status, with a performance-diagnostics guide#231

Add query-latency and Solr health metrics to /status, with a performance-diagnostics guide#231
gaurav wants to merge 25 commits into
mainfrom
track-recent-times

gaurav commented Dec 18, 2025 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Copilot AI Apr 7, 2026

Uh oh!

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

gaurav commented Jul 27, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

	recent_query_times.append(time_taken_ms)
	recent_query_times.append(time_taken_ms_solr)

Uh oh!

Conversation

gaurav commented Dec 18, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

/status — always on (no Solr round-trip)

/status?full=true — solr_metrics (one /admin/metrics round-trip)

Documentation

Companion deployment changes (separate repo)

Design notes

Testing

Related

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Uh oh!

Uh oh!

Copilot AI Apr 7, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

gaurav commented Jul 27, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

gaurav commented Dec 18, 2025 •

edited

Loading

`/status` — always on (no Solr round-trip)

`/status?full=true` — `solr_metrics` (one `/admin/metrics` round-trip)