From 3d37f2eac1784145c5ac8633fd15e91ad8f97111 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 15:53:04 -0500 Subject: [PATCH 01/37] Renamed LOGGER to logger. --- api/server.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/api/server.py b/api/server.py index 3c3ec88a..6662ce76 100755 --- a/api/server.py +++ b/api/server.py @@ -21,11 +21,11 @@ from .apidocs import get_app_info, construct_open_api_schema -LOGGER = logging.getLogger(__name__) SOLR_HOST = os.getenv("SOLR_HOST", "localhost") SOLR_PORT = os.getenv("SOLR_PORT", "8983") app = FastAPI(**get_app_info()) +logger = logging.getLogger(__name__) app.add_middleware( CORSMiddleware, @@ -63,7 +63,7 @@ async def status() -> Dict: 'action': 'STATUS' }) if response.status_code >= 300: - LOGGER.error("Solr error on accessing /solr/admin/cores?action=STATUS: %s", response.text) + logger.error("Solr error on accessing /solr/admin/cores?action=STATUS: %s", response.text) response.raise_for_status() result = response.json() @@ -465,7 +465,7 @@ async def lookup(string: str, async with httpx.AsyncClient(timeout=None) as client: response = await client.post(query_url, json=params) if response.status_code >= 300: - LOGGER.error("Solr REST error: %s", response.text) + logger.error("Solr REST error: %s", response.text) response.raise_for_status() response = response.json() logging.debug(f"Solr response: {json.dumps(response, indent=2)}") From 4d271de75afdf2dabd502099493776c2ab87a2b1 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 16:02:29 -0500 Subject: [PATCH 02/37] Added logging to /synonyms API endpoint. --- api/server.py | 30 +++++++++++++++++++----------- 1 file changed, 19 insertions(+), 11 deletions(-) diff --git a/api/server.py b/api/server.py index 6662ce76..bffe7023 100755 --- a/api/server.py +++ b/api/server.py @@ -8,7 +8,9 @@ * Matching names are returned first, followed by non-matching names """ import json -import logging, warnings +import logging +import time +import warnings import os import re from typing import Dict, List, Union, Annotated, Optional @@ -19,13 +21,14 @@ from pydantic import BaseModel, conint, Field from starlette.middleware.cors import CORSMiddleware -from .apidocs import get_app_info, construct_open_api_schema +from api.apidocs import get_app_info, construct_open_api_schema SOLR_HOST = os.getenv("SOLR_HOST", "localhost") SOLR_PORT = os.getenv("SOLR_PORT", "8983") app = FastAPI(**get_app_info()) logger = logging.getLogger(__name__) +logging.basicConfig(level=os.getenv("LOGLEVEL", logging.INFO)) app.add_middleware( CORSMiddleware, @@ -125,7 +128,7 @@ async def reverse_lookup_get( ) ) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" - return await reverse_lookup(curies) + return await curie_lookup(curies) @app.get( @@ -135,14 +138,14 @@ async def reverse_lookup_get( response_model=Dict[str, Dict], tags=["lookup"], ) -async def lookup_names_get( +async def synonyms_get( preferred_curies: List[str]= Query( example=["MONDO:0005737", "MONDO:0009757"], description="A list of CURIEs to look up synonyms for." ) ) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" - return await reverse_lookup(preferred_curies) + return await curie_lookup(preferred_curies) @app.post( @@ -159,7 +162,7 @@ async def lookup_names_post( }), ) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" - return await reverse_lookup(request.curies) + return await curie_lookup(request.curies) @app.post( @@ -169,17 +172,18 @@ async def lookup_names_post( response_model=Dict[str, Dict], tags=["lookup"], ) -async def lookup_names_post( +async def synonyms_post( request: SynonymsRequest = Body(..., example={ "preferred_curies": ["MONDO:0005737", "MONDO:0009757"], }), ) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" - return await reverse_lookup(request.preferred_curies) + return await curie_lookup(request.preferred_curies) -async def reverse_lookup(curies) -> Dict[str, Dict]: +async def curie_lookup(curies) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" + time_start = time.time_ns() query = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/select" curie_filter = " OR ".join( f"curie:\"{curie}\"" @@ -199,6 +203,10 @@ async def reverse_lookup(curies) -> Dict[str, Dict]: } for doc in response_json["response"]["docs"]: output[doc["curie"]] = doc + time_end = time.time_ns() + + logging.info(f"CURIE Lookup on {len(curies)} CURIEs {json.dumps(curies)} took {(time_end - time_start)/1_000_000:.2f}ms") + return output class LookupResult(BaseModel): @@ -459,7 +467,7 @@ async def lookup(string: str, "fields": "*, score", "params": inner_params, } - logging.debug(f"Query: {json.dumps(params, indent=2)}") + logger.debug(f"Query: {json.dumps(params, indent=2)}") query_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/select" async with httpx.AsyncClient(timeout=None) as client: @@ -468,7 +476,7 @@ async def lookup(string: str, logger.error("Solr REST error: %s", response.text) response.raise_for_status() response = response.json() - logging.debug(f"Solr response: {json.dumps(response, indent=2)}") + logger.debug(f"Solr response: {json.dumps(response, indent=2)}") # Associate highlighting information with search results. highlighting_response = response.get("highlighting", {}) From 096f79c069efae006a2590f966b2f7842fe8970b Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 16:15:11 -0500 Subject: [PATCH 03/37] Added logging to Lookup. --- api/server.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/api/server.py b/api/server.py index bffe7023..d3f37e1b 100755 --- a/api/server.py +++ b/api/server.py @@ -359,6 +359,8 @@ async def lookup(string: str, will be returned, rather than filtering to concepts that are both PhenotypicFeature and Disease. """ + time_start = time.time_ns() + # First, we strip and lowercase the query since all our indexes are case-insensitive. string_lc = string.strip().lower() @@ -469,6 +471,7 @@ async def lookup(string: str, } logger.debug(f"Query: {json.dumps(params, indent=2)}") + time_solr_start = time.time_ns() query_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/select" async with httpx.AsyncClient(timeout=None) as client: response = await client.post(query_url, json=params) @@ -476,6 +479,7 @@ async def lookup(string: str, logger.error("Solr REST error: %s", response.text) response.raise_for_status() response = response.json() + time_solr_end = time.time_ns() logger.debug(f"Solr response: {json.dumps(response, indent=2)}") # Associate highlighting information with search results. @@ -519,6 +523,12 @@ async def lookup(string: str, clique_identifier_count=doc.get("clique_identifier_count", 0), types=[f"biolink:{d}" for d in doc.get("types", [])])) + time_end = time.time_ns() + logging.info(f"Lookup query to Solr for {json.dumps(string)} " + + f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, biolink_types={biolink_types}, only_prefixes={only_prefixes}, exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}) " + f"took {(time_end - time_start)/1_000_000:.2f}ms (with {(time_solr_end - time_solr_start)/1_000_000:.2f}ms waiting for Solr)" + ) + return outputs ## BULK ENDPOINT From 923e0792eb69b67ee007fca454e1ac78f837c7ba Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 16:20:14 -0500 Subject: [PATCH 04/37] Added logging for bulk_lookup(). --- api/server.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/api/server.py b/api/server.py index d3f37e1b..fb5a68a7 100755 --- a/api/server.py +++ b/api/server.py @@ -205,7 +205,7 @@ async def curie_lookup(curies) -> Dict[str, Dict]: output[doc["curie"]] = doc time_end = time.time_ns() - logging.info(f"CURIE Lookup on {len(curies)} CURIEs {json.dumps(curies)} took {(time_end - time_start)/1_000_000:.2f}ms") + logger.info(f"CURIE Lookup on {len(curies)} CURIEs {json.dumps(curies)} took {(time_end - time_start)/1_000_000:.2f}ms") return output @@ -524,7 +524,7 @@ async def lookup(string: str, types=[f"biolink:{d}" for d in doc.get("types", [])])) time_end = time.time_ns() - logging.info(f"Lookup query to Solr for {json.dumps(string)} " + + logger.info(f"Lookup query to Solr for {json.dumps(string)} " + f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, biolink_types={biolink_types}, only_prefixes={only_prefixes}, exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}) " f"took {(time_end - time_start)/1_000_000:.2f}ms (with {(time_solr_end - time_solr_start)/1_000_000:.2f}ms waiting for Solr)" ) @@ -597,6 +597,7 @@ class NameResQuery(BaseModel): tags=["lookup"] ) async def bulk_lookup(query: NameResQuery) -> Dict[str, List[LookupResult]]: + time_start = time.time_ns() result = {} for string in query.strings: result[string] = await lookup( @@ -609,6 +610,9 @@ async def bulk_lookup(query: NameResQuery) -> Dict[str, List[LookupResult]]: query.only_prefixes, query.exclude_prefixes, query.only_taxa) + time_end = time.time_ns() + logger.info(f"Bulk lookup query for {len(query.strings)} strings ({query}) took {(time_end - time_start)/1_000_000:.2f}ms") + return result From c8ae693c175343e203bb9c338154a82a1c390c06 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 17:54:02 -0500 Subject: [PATCH 05/37] Added NameRes version to /status. --- api/server.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index fb5a68a7..67fd135c 100755 --- a/api/server.py +++ b/api/server.py @@ -74,6 +74,11 @@ async def status() -> Dict: babel_version = os.environ.get("BABEL_VERSION", "unknown") babel_version_url = os.environ.get("BABEL_VERSION_URL", "") + # Figure out the NameRes version. + nameres_version = "unknown" + if 'version' in get_app_info(): + nameres_version = 'v' + get_app_info()['version'] + # We should have a status for name_lookup_shard1_replica_n1. if 'status' in result and 'name_lookup_shard1_replica_n1' in result['status']: core = result['status']['name_lookup_shard1_replica_n1'] @@ -87,6 +92,7 @@ async def status() -> Dict: 'message': 'Reporting results from primary core.', 'babel_version': babel_version, 'babel_version_url': babel_version_url, + 'nameres_version': nameres_version, 'startTime': core['startTime'], 'numDocs': index.get('numDocs', ''), 'maxDoc': index.get('maxDoc', ''), @@ -99,7 +105,8 @@ async def status() -> Dict: else: return { 'status': 'error', - 'message': 'Expected core not found.' + 'message': 'Expected core not found.', + 'nameres_version': nameres_version, } From bc0265058b0761e95ce36c8647d8719119cacc40 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 17:59:50 -0500 Subject: [PATCH 06/37] Added BIOLINK_MODEL_TAG. --- api/server.py | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/api/server.py b/api/server.py index 67fd135c..c6328384 100755 --- a/api/server.py +++ b/api/server.py @@ -74,10 +74,16 @@ async def status() -> Dict: babel_version = os.environ.get("BABEL_VERSION", "unknown") babel_version_url = os.environ.get("BABEL_VERSION_URL", "") + # Look up the BIOLINK_MODEL_TAG. + biolink_model_tag = os.environ.get("BIOLINK_MODEL_TAG", "master") # Note that this should be a tag from the Biolink Model repo, e.g. "master" or "v4.3.6". + biolink_model_url = f"https://github.com/biolink/biolink-model/tree/{biolink_model_tag}" + biolink_model_download_url = f"https://raw.githubusercontent.com/biolink/biolink-model/{biolink_model_tag}/biolink-model.yaml" + # Figure out the NameRes version. - nameres_version = "unknown" - if 'version' in get_app_info(): - nameres_version = 'v' + get_app_info()['version'] + nameres_version = "master" + app_info = get_app_info() + if 'version' in app_info and app_info['version']: + nameres_version = 'v' + app_info['version'] # We should have a status for name_lookup_shard1_replica_n1. if 'status' in result and 'name_lookup_shard1_replica_n1' in result['status']: @@ -92,6 +98,11 @@ async def status() -> Dict: 'message': 'Reporting results from primary core.', 'babel_version': babel_version, 'babel_version_url': babel_version_url, + 'biolink_model': { + 'tag': biolink_model_tag, + 'url': biolink_model_url, + 'download_url': biolink_model_download_url, + }, 'nameres_version': nameres_version, 'startTime': core['startTime'], 'numDocs': index.get('numDocs', ''), From 9c255ece1010ae20abf6df9ed45a9bff99c491cd Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:17:41 -0500 Subject: [PATCH 07/37] Added basic tests for /status. --- tests/test_status.py | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) create mode 100644 tests/test_status.py diff --git a/tests/test_status.py b/tests/test_status.py new file mode 100644 index 00000000..9d037ac4 --- /dev/null +++ b/tests/test_status.py @@ -0,0 +1,27 @@ +import logging + +from api.server import app +from fastapi.testclient import TestClient + +# Turn on debugging for tests. +logging.basicConfig(level=logging.DEBUG) + +def test_status(): + client = TestClient(app) + response = client.get("/status") + status = response.json() + + assert status['status'] == 'ok' + assert status['message'] != '' + assert 'babel_version' in status + assert 'babel_version_url' in status + assert 'biolink_model' in status + assert 'tag' in status['biolink_model'] + assert 'nameres_version' in status + + assert status['startTime'] + assert status['numDocs'] == 32 + assert status['maxDocs'] == 32 + assert status['deletedDocs'] == 0 + assert status['version'].startswith('9.') + assert status['size'] != '' From 27f9f4b99be27034c57d825c2e99ec11946f661e Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:20:26 -0500 Subject: [PATCH 08/37] Improved tests. --- tests/test_status.py | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/tests/test_status.py b/tests/test_status.py index 9d037ac4..d6708933 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -18,10 +18,12 @@ def test_status(): assert 'biolink_model' in status assert 'tag' in status['biolink_model'] assert 'nameres_version' in status - - assert status['startTime'] - assert status['numDocs'] == 32 - assert status['maxDocs'] == 32 - assert status['deletedDocs'] == 0 assert status['version'].startswith('9.') assert status['size'] != '' + assert status['startTime'] + + # Count the specific number of test documents we load. + assert status['numDocs'] == 89 + assert status['maxDocs'] == 89 + assert status['deletedDocs'] == 0 + From d4d23b19085595888b7b2356a51132b8a355f2b2 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:25:03 -0500 Subject: [PATCH 09/37] Attempted to fix issues. --- tests/test_status.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_status.py b/tests/test_status.py index d6708933..47e78381 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -18,7 +18,7 @@ def test_status(): assert 'biolink_model' in status assert 'tag' in status['biolink_model'] assert 'nameres_version' in status - assert status['version'].startswith('9.') + assert status['version'] > 1 assert status['size'] != '' assert status['startTime'] From b19316c032388ded96b80b986466054794e46743 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:32:45 -0500 Subject: [PATCH 10/37] Fixed key name. --- tests/test_status.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_status.py b/tests/test_status.py index 47e78381..b48ddc07 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -24,6 +24,6 @@ def test_status(): # Count the specific number of test documents we load. assert status['numDocs'] == 89 - assert status['maxDocs'] == 89 + assert status['maxDoc'] == 89 assert status['deletedDocs'] == 0 From 7f025006e91752984ac191dbf8fb56805e572906 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:35:47 -0500 Subject: [PATCH 11/37] Update api/server.py Error message should include variables we've already computed. Could be useful. Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- api/server.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/api/server.py b/api/server.py index c6328384..7c0b74e3 100755 --- a/api/server.py +++ b/api/server.py @@ -117,6 +117,13 @@ async def status() -> Dict: return { 'status': 'error', 'message': 'Expected core not found.', + 'babel_version': babel_version, + 'babel_version_url': babel_version_url, + 'biolink_model': { + 'tag': biolink_model_tag, + 'url': biolink_model_url, + 'download_url': biolink_model_download_url, + }, 'nameres_version': nameres_version, } From 3a2bbc900cb4c7b81edfe548f0e826718302444b Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Fri, 20 Feb 2026 18:36:04 -0500 Subject: [PATCH 12/37] Update api/server.py Improved comment. Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- api/server.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index 7c0b74e3..e54d35a5 100755 --- a/api/server.py +++ b/api/server.py @@ -75,7 +75,8 @@ async def status() -> Dict: babel_version_url = os.environ.get("BABEL_VERSION_URL", "") # Look up the BIOLINK_MODEL_TAG. - biolink_model_tag = os.environ.get("BIOLINK_MODEL_TAG", "master") # Note that this should be a tag from the Biolink Model repo, e.g. "master" or "v4.3.6". + # Note: this should be a tag from the Biolink Model repo, e.g. "master" or "v4.3.6". + biolink_model_tag = os.environ.get("BIOLINK_MODEL_TAG", "master") biolink_model_url = f"https://github.com/biolink/biolink-model/tree/{biolink_model_tag}" biolink_model_download_url = f"https://raw.githubusercontent.com/biolink/biolink-model/{biolink_model_tag}/biolink-model.yaml" From f7267dc6d650c6725c4c73661f6f80ab4cd27e31 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 16:46:31 -0500 Subject: [PATCH 13/37] Added a "recent times" that allows us to track query times. --- api/server.py | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index e54d35a5..84cd9044 100755 --- a/api/server.py +++ b/api/server.py @@ -13,6 +13,7 @@ import warnings import os import re +from collections import deque from typing import Dict, List, Union, Annotated, Optional from fastapi import Body, FastAPI, Query @@ -38,6 +39,10 @@ allow_headers=["*"], ) +# We track the time taken for each Solr query for the last 1000 queries so we can track performance via /status. +RECENT_TIMES_COUNT = os.getenv("RECENT_TIMES_COUNT", 1000) +recent_query_times = deque(maxlen=RECENT_TIMES_COUNT) + # ENDPOINT / # If someone tries accessing /, we should redirect them to the Swagger interface. @app.get("/", include_in_schema=False) @@ -113,6 +118,11 @@ async def status() -> Dict: 'segmentCount': index.get('segmentCount', ''), 'lastModified': index.get('lastModified', ''), 'size': index.get('size', ''), + 'recent_queries': { + 'count': len(recent_query_times), + 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, + 'recent_time_ms': list(recent_query_times), + } } else: return { @@ -550,9 +560,11 @@ async def lookup(string: str, types=[f"biolink:{d}" for d in doc.get("types", [])])) time_end = time.time_ns() + time_taken_ms = (time_end - time_start)/1_000_000 + recent_query_times.append(time_taken_ms) logger.info(f"Lookup query to Solr for {json.dumps(string)} " + f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, biolink_types={biolink_types}, only_prefixes={only_prefixes}, exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}) " - f"took {(time_end - time_start)/1_000_000:.2f}ms (with {(time_solr_end - time_solr_start)/1_000_000:.2f}ms waiting for Solr)" + f"took {time_taken_ms:.2f}ms (with {(time_solr_end - time_solr_start)/1_000_000:.2f}ms waiting for Solr)" ) return outputs From 9c89abffbe076500f33c3b5b8e90cc6d2118f00a Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Thu, 18 Dec 2025 16:53:48 -0500 Subject: [PATCH 14/37] Improved name. --- api/server.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index 84cd9044..906c7db9 100755 --- a/api/server.py +++ b/api/server.py @@ -121,7 +121,7 @@ async def status() -> Dict: 'recent_queries': { 'count': len(recent_query_times), 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, - 'recent_time_ms': list(recent_query_times), + 'recent_times_ms': list(recent_query_times), } } else: From a0707a669fdfae92da927c1f73b5813a22037caf Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 15:38:46 -0400 Subject: [PATCH 15/37] Apply suggestion from @gaurav --- api/server.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index 906c7db9..84949b55 100755 --- a/api/server.py +++ b/api/server.py @@ -22,7 +22,7 @@ from pydantic import BaseModel, conint, Field from starlette.middleware.cors import CORSMiddleware -from api.apidocs import get_app_info, construct_open_api_schema +from .apidocs import get_app_info, construct_open_api_schema SOLR_HOST = os.getenv("SOLR_HOST", "localhost") SOLR_PORT = os.getenv("SOLR_PORT", "8983") From a3e00f8666e4d18c089e23f6025eee2cf3a37546 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 13:52:54 -0600 Subject: [PATCH 16/37] Add Solr performance diagnostics to /status and logging - /status now fetches JVM heap, CPU load, and OS memory from Solr's admin/info/system endpoint (in parallel with existing core status call) - /status now fetches filterCache and queryResultCache hit ratios and eviction counts from Solr's MBeans endpoint - recent_queries in /status now includes p50/p95/p99 percentiles alongside the existing mean, to distinguish GC pauses from sustained load - lookup() now emits WARNING instead of INFO for queries exceeding SLOW_QUERY_THRESHOLD_MS (default 500ms, configurable via env var) - Added documentation/Performance.md with a diagnostic decision tree explaining how to use these metrics to identify CPU vs memory pressure Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 126 +++++++++++++++++++--- documentation/Performance.md | 200 +++++++++++++++++++++++++++++++++++ 2 files changed, 310 insertions(+), 16 deletions(-) create mode 100644 documentation/Performance.md diff --git a/api/server.py b/api/server.py index 84949b55..58e6877a 100755 --- a/api/server.py +++ b/api/server.py @@ -7,8 +7,10 @@ * The curie with the shortest match is first, etc. * Matching names are returned first, followed by non-matching names """ +import asyncio import json import logging +import statistics import time import warnings import os @@ -43,6 +45,9 @@ RECENT_TIMES_COUNT = os.getenv("RECENT_TIMES_COUNT", 1000) recent_query_times = deque(maxlen=RECENT_TIMES_COUNT) +# Queries slower than this threshold will be logged at WARNING level (see documentation/Performance.md). +SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) + # ENDPOINT / # If someone tries accessing /, we should redirect them to the Swagger interface. @app.get("/", include_in_schema=False) @@ -65,15 +70,39 @@ async def status_get() -> Dict: async def status() -> Dict: """ Return a dictionary containing status and count information for the underlying Solr instance. """ - query_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/cores" + cores_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/cores" + sysinfo_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/info/system" + mbeans_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/admin/mbeans" + + async def fetch_sysinfo(client): + try: + r = await client.get(sysinfo_url, params={"wt": "json"}) + r.raise_for_status() + return r.json() + except Exception as e: + logger.warning("Could not fetch Solr system info: %s", e) + return None + + async def fetch_cache_mbeans(client): + try: + r = await client.get(mbeans_url, params={"cat": "CACHE", "stats": "true", "wt": "json"}) + r.raise_for_status() + return r.json() + except Exception as e: + logger.warning("Could not fetch Solr cache MBeans: %s", e) + return None + async with httpx.AsyncClient(timeout=None) as client: - response = await client.get(query_url, params={ - 'action': 'STATUS' - }) - if response.status_code >= 300: - logger.error("Solr error on accessing /solr/admin/cores?action=STATUS: %s", response.text) - response.raise_for_status() - result = response.json() + cores_response, sysinfo_data, mbeans_data = await asyncio.gather( + client.get(cores_url, params={"action": "STATUS"}), + fetch_sysinfo(client), + fetch_cache_mbeans(client), + ) + + if cores_response.status_code >= 300: + logger.error("Solr error on accessing /solr/admin/cores?action=STATUS: %s", cores_response.text) + cores_response.raise_for_status() + result = cores_response.json() # Do we know the Babel version and version URL? It will be stored in an environmental variable if we do. babel_version = os.environ.get("BABEL_VERSION", "unknown") @@ -91,6 +120,62 @@ async def status() -> Dict: if 'version' in app_info and app_info['version']: nameres_version = 'v' + app_info['version'] + # Build JVM and OS info from the system info response. + jvm_info = None + os_info = None + if sysinfo_data: + jvm_raw = sysinfo_data.get("jvm", {}).get("memory", {}).get("raw", {}) + heap_used = jvm_raw.get("used") + heap_max = jvm_raw.get("max") + jvm_info = { + "heap_used_bytes": heap_used, + "heap_max_bytes": heap_max, + "heap_used_pct": round(heap_used / heap_max, 4) if heap_used and heap_max else None, + } + system = sysinfo_data.get("system", {}) + os_info = { + "process_cpu_load": system.get("processCpuLoad"), + "system_cpu_load": system.get("systemCpuLoad"), + "free_physical_memory_bytes": system.get("freePhysicalMemorySize"), + "total_physical_memory_bytes": system.get("totalPhysicalMemorySize"), + } + + # Build cache stats from the MBeans response. + cache_info = None + if mbeans_data: + def extract_cache(name): + for entry in mbeans_data.get("solr-mbeans", []): + if isinstance(entry, dict) and name in entry: + stats = entry[name].get("stats", {}) + return { + "hitratio": stats.get("hitratio"), + "evictions": stats.get("evictions"), + "size": stats.get("size"), + "maxSize": stats.get("maxSize"), + } + return None + cache_info = { + "filterCache": extract_cache("filterCache"), + "queryResultCache": extract_cache("queryResultCache"), + } + + # Compute percentiles from recent query times. + times = list(recent_query_times) + if len(times) >= 2: + qs = statistics.quantiles(times, n=100) + p50, p95, p99 = qs[49], qs[94], qs[98] + else: + p50 = p95 = p99 = None + + recent_queries = { + 'count': len(recent_query_times), + 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, + 'p50_ms': p50, + 'p95_ms': p95, + 'p99_ms': p99, + 'recent_times_ms': list(recent_query_times), + } + # We should have a status for name_lookup_shard1_replica_n1. if 'status' in result and 'name_lookup_shard1_replica_n1' in result['status']: core = result['status']['name_lookup_shard1_replica_n1'] @@ -118,11 +203,10 @@ async def status() -> Dict: 'segmentCount': index.get('segmentCount', ''), 'lastModified': index.get('lastModified', ''), 'size': index.get('size', ''), - 'recent_queries': { - 'count': len(recent_query_times), - 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, - 'recent_times_ms': list(recent_query_times), - } + 'recent_queries': recent_queries, + 'jvm': jvm_info, + 'os': os_info, + 'cache': cache_info, } else: return { @@ -136,6 +220,8 @@ async def status() -> Dict: 'download_url': biolink_model_download_url, }, 'nameres_version': nameres_version, + 'jvm': jvm_info, + 'os': os_info, } @@ -561,11 +647,19 @@ async def lookup(string: str, time_end = time.time_ns() time_taken_ms = (time_end - time_start)/1_000_000 + solr_ms = (time_solr_end - time_solr_start)/1_000_000 recent_query_times.append(time_taken_ms) - logger.info(f"Lookup query to Solr for {json.dumps(string)} " + - f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, biolink_types={biolink_types}, only_prefixes={only_prefixes}, exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}) " - f"took {time_taken_ms:.2f}ms (with {(time_solr_end - time_solr_start)/1_000_000:.2f}ms waiting for Solr)" + log_msg = ( + f"Lookup query to Solr for {json.dumps(string)} " + f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, " + f"biolink_types={biolink_types}, only_prefixes={only_prefixes}, exclude_prefixes={exclude_prefixes}, " + f"only_taxa={only_taxa}) " + f"took {time_taken_ms:.2f}ms (with {solr_ms:.2f}ms waiting for Solr)" ) + if time_taken_ms > SLOW_QUERY_THRESHOLD_MS: + logger.warning("SLOW QUERY: " + log_msg) + else: + logger.info(log_msg) return outputs diff --git a/documentation/Performance.md b/documentation/Performance.md new file mode 100644 index 00000000..cf09c96e --- /dev/null +++ b/documentation/Performance.md @@ -0,0 +1,200 @@ +# NameRes Performance Diagnostics + +This document explains how to diagnose why Solr may be slow or under strain, using the +observability built into NameRes. It covers what the existing metrics mean, what additional +metrics can be added to the code, and a decision tree for identifying CPU pressure, memory +pressure, and other causes. + +--- + +## 1. Current observability + +### `GET /status` — response fields + +| Field | What it means | +|---|---| +| `recent_queries.mean_time_ms` | Average round-trip time (Python → Solr → Python) for the last N queries (N set by `RECENT_TIMES_COUNT`, default 1000). Rising mean = sustained slowdown. | +| `recent_queries.recent_times_ms` | The raw list of timings. Scan for a long tail of high values (occasional spikes) vs. a uniformly elevated distribution (sustained slowness). | +| `segmentCount` | Number of Lucene segments in the index. A value above ~20 means Solr is doing more per-segment work per query. Consider triggering a Solr optimize (`/solr/name_lookup/update?optimize=true`). | +| `numDocs` / `maxDoc` | `maxDoc - numDocs = deletedDocs` (soft deletes not yet merged). A very high deleted count combined with high segment count amplifies query cost. | +| `size` | Index size on disk. Unexpectedly small may indicate an incomplete data load. | + +### Log messages + +Every call to `lookup()` emits a line at INFO level: + +``` +INFO: Lookup query to Solr for "diabetes" (autocomplete=False, highlighting=False, offset=0, limit=10, + biolink_types=['biolink:Disease'], only_prefixes=None, exclude_prefixes=None, only_taxa=None) + took 123.45ms (with 100.12ms waiting for Solr) +``` + +Key interpretation: +- **"waiting for Solr" ≈ total** → the bottleneck is inside Solr (JVM, index, caches). +- **"waiting for Solr" is small but total is high** → the bottleneck is in Python result processing + (e.g., large result sets being deserialized or filtered). +- **Consistent high "waiting for Solr"** → follow the decision tree below. + +--- + +## 2. Proposed additional metrics + +The following additions to `api/server.py` would give full visibility into Solr internals. +Each is independent and can be implemented separately. + +### 2a. JVM and OS info + +Add a call to `/solr/admin/info/system?wt=json` in the `status()` function, run in parallel +with the existing `/solr/admin/cores` call using `asyncio.gather()`. Expose these fields in +the status response under `"jvm"` and `"os"` keys: + +| New field | Solr JSON path | What it diagnoses | +|---|---|---| +| `jvm.heap_used_pct` | `jvm.memory.raw.used / jvm.memory.raw.max` | **>80% = memory pressure** | +| `jvm.heap_used_bytes` | `jvm.memory.raw.used` | Absolute heap consumption | +| `jvm.heap_max_bytes` | `jvm.memory.raw.max` | JVM -Xmx ceiling | +| `os.process_cpu_load` | `system.processCpuLoad` (0.0–1.0) | **>0.8 = CPU saturation** | +| `os.system_cpu_load` | `system.systemCpuLoad` (0.0–1.0) | Host-wide CPU (other processes) | +| `os.free_physical_memory_bytes` | `system.freePhysicalMemorySize` | OS RAM available to JVM | +| `os.total_physical_memory_bytes` | `system.totalPhysicalMemorySize` | Total host RAM | + +Example `status()` change (simplified): +```python +import asyncio, statistics + +async with httpx.AsyncClient(timeout=None) as client: + cores_resp, sysinfo_resp, mbeans_resp = await asyncio.gather( + client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/cores", params={"action": "STATUS"}), + client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/info/system", params={"wt": "json"}), + client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/admin/mbeans", + params={"cat": "CACHE", "stats": "true", "wt": "json"}), + ) +``` + +### 2b. Cache hit/eviction statistics + +From the MBeans call above, extract Solr's internal cache statistics under a `"cache"` key: + +| New field | What to watch for | +|---|---| +| `cache.filterCache.hitratio` | Should be >0.9. Below 0.5 = Solr re-computing every filter query. | +| `cache.filterCache.evictions` | Rising count = cache too small for the query working set. | +| `cache.queryResultCache.hitratio` | Same interpretation as filterCache. | +| `cache.queryResultCache.evictions` | Same interpretation as filterCache. | + +Cache sizes are configured in Solr's `solrconfig.xml`. If evictions are high, increase +`` for the affected cache, or investigate whether requests use many distinct +filter combinations that will never cache well. + +### 2c. Query time percentiles + +The existing `recent_query_times` deque holds up to 1000 timings. Currently only the mean +is exposed. Add p50/p95/p99 to `recent_queries` using `statistics.quantiles(data, n=100)`: + +```python +import statistics +times = list(recent_query_times) +if len(times) >= 2: + qs = statistics.quantiles(times, n=100) + p50, p95, p99 = qs[49], qs[94], qs[98] +``` + +These distinguish: +- **p50 rising** = sustained overload (every query is slow) +- **p99 spiking but p50 stable** = occasional GC pauses or one-off expensive queries + +### 2d. Slow query warning logs + +Add an environment variable `SLOW_QUERY_THRESHOLD_MS` (default: 500). In `lookup()`, after +the existing INFO log line, add: + +```python +SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) + +# ... inside lookup(), after computing time_taken_ms: +if time_taken_ms > SLOW_QUERY_THRESHOLD_MS: + logger.warning( + f"SLOW QUERY ({time_taken_ms:.2f}ms, {solr_ms:.2f}ms in Solr): " + f"query={json.dumps(string)}, autocomplete={autocomplete}, " + f"biolink_types={biolink_types}, only_prefixes={only_prefixes}, " + f"exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}, " + f"results={len(outputs)}" + ) +``` + +This surfaces outlier queries in log aggregators (e.g., CloudWatch, Datadog) without +needing to poll the status endpoint or scan INFO-level logs. + +--- + +## 3. Diagnostic decision tree + +Use this when Solr seems slow or unresponsive. + +``` +Solr seems slow or strained +│ +├─ Step 1: Check logs for "waiting for Solr" vs total time +│ │ +│ ├─ "waiting for Solr" is small, total is high +│ │ → Python result-processing bottleneck +│ │ Check: large result sets (increase Solr's limit param or reduce result size) +│ │ Check: Python CPU at capacity (scale horizontally) +│ │ +│ └─ "waiting for Solr" is most of total → problem is INSIDE Solr → continue below +│ +├─ Step 2: Check jvm.heap_used_pct in /status (requires 2a above) +│ │ +│ ├─ >80% → MEMORY PRESSURE +│ │ │ +│ │ ├─ Check cache.filterCache.evictions (requires 2b above) +│ │ │ ├─ Rising evictions → cache is too small +│ │ │ │ Fix: increase in Solr's solrconfig.xml filterCache config +│ │ │ └─ No evictions but heap still high → data itself is large +│ │ │ Fix: increase JVM -Xmx (SOLR_JAVA_MEM in Solr's env config) +│ │ │ or add more RAM to the host +│ │ │ +│ │ └─ Heap high AND evictions low → not a cache problem +│ │ Consider: index warming, Solr fieldCache for sorted fields +│ │ +│ └─ <50% → NOT a memory issue → continue +│ +├─ Step 3: Check os.process_cpu_load in /status (requires 2a above) +│ │ +│ ├─ >0.8 → CPU SATURATION +│ │ │ +│ │ ├─ Check segmentCount in /status +│ │ │ ├─ >20 → run Solr optimize to merge segments +│ │ │ │ POST http://solr-host:8983/solr/name_lookup/update?optimize=true +│ │ │ └─ Low segmentCount → CPU is busy with query evaluation +│ │ │ +│ │ ├─ Check slow-query WARNINGs in logs (requires 2d above) +│ │ │ Are expensive queries (many filters, wildcard-heavy) driving the load? +│ │ │ Fix: cache common filter combinations; avoid leading wildcards in queries +│ │ │ +│ │ └─ Even load across all queries → scale horizontally (add Solr replicas) +│ │ +│ └─ Low CPU and low memory with slow queries → likely GC pauses → continue +│ +└─ Step 4: Check p99 vs p50 (requires 2c above) + │ + ├─ p99 >> p50 (e.g. p50=50ms, p99=5000ms) → GC pause signature + │ Fix: tune JVM GC settings + │ -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:G1HeapRegionSize=... + │ Check Solr GC logs (solr-gc.log) for Full GC frequency + │ + └─ p50 and p99 both high → Solr is overloaded at all percentiles + → All of the above apply; start with memory (Step 2) +``` + +--- + +## 4. Quick reference: environment variables + +| Variable | Default | Effect | +|---|---|---| +| `SOLR_HOST` | `localhost` | Solr hostname | +| `SOLR_PORT` | `8983` | Solr port | +| `RECENT_TIMES_COUNT` | `1000` | How many recent query times to track | +| `SLOW_QUERY_THRESHOLD_MS` | `500` | Log a WARNING for queries slower than this (requires code change 2d) | +| `LOGLEVEL` | `INFO` | Set to `DEBUG` to log full Solr request/response JSON | From fc168b878a06b71eeedf0afcc39547466f60f0fe Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 13:53:12 -0600 Subject: [PATCH 17/37] Added on:pull_request trigger for testing. --- .github/workflows/release-name-resolution.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/release-name-resolution.yml b/.github/workflows/release-name-resolution.yml index e5773778..f2f9175c 100644 --- a/.github/workflows/release-name-resolution.yml +++ b/.github/workflows/release-name-resolution.yml @@ -1,6 +1,7 @@ name: 'Release a new version of NameResolution to Github Packages' on: + pull_request: release: types: [published] From 397996816014ad6328fad15c0332e6cbe608d949 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 14:54:04 -0600 Subject: [PATCH 18/37] Add query rate estimation to /status Tracks query start timestamps in a separate deque (RECENT_QUERY_TIMESTAMPS_COUNT, default 50k entries) independent of the latency deque. /status now reports queries_last_60s, queries_per_second_last_60s, queries_last_300s, and queries_per_second_last_300s under recent_queries.rate. The large deque size ensures rate estimates remain meaningful at high query rates (500 qps fills 1000 entries in 2s but covers 100s with 50k entries). Rate is computed by scanning from newest to oldest and stopping at the window boundary, so it's O(window_size) not O(deque_size). Updated documentation/Performance.md to reflect all implemented metrics and added query rate as Step 1 in the diagnostic decision tree. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 26 ++++ documentation/Performance.md | 230 ++++++++++++++++------------------- 2 files changed, 130 insertions(+), 126 deletions(-) diff --git a/api/server.py b/api/server.py index 58e6877a..1eba7c5b 100755 --- a/api/server.py +++ b/api/server.py @@ -45,6 +45,11 @@ RECENT_TIMES_COUNT = os.getenv("RECENT_TIMES_COUNT", 1000) recent_query_times = deque(maxlen=RECENT_TIMES_COUNT) +# We track query start timestamps separately for rate estimation (see documentation/Performance.md). +# A larger maxlen allows rate computation over meaningful windows even at high query rates. +RECENT_QUERY_TIMESTAMPS_COUNT = int(os.getenv("RECENT_QUERY_TIMESTAMPS_COUNT", 50000)) +recent_query_timestamps = deque(maxlen=RECENT_QUERY_TIMESTAMPS_COUNT) + # Queries slower than this threshold will be logged at WARNING level (see documentation/Performance.md). SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) @@ -167,6 +172,20 @@ def extract_cache(name): else: p50 = p95 = p99 = None + # Compute query rates from the timestamp deque. Scan from the right (newest) so we stop + # early for short windows rather than walking the whole deque. + now = time.time() + count_60s = 0 + count_300s = 0 + for ts in reversed(recent_query_timestamps): + age = now - ts + if age <= 300: + count_300s += 1 + if age <= 60: + count_60s += 1 + else: + break + recent_queries = { 'count': len(recent_query_times), 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, @@ -174,6 +193,12 @@ def extract_cache(name): 'p95_ms': p95, 'p99_ms': p99, 'recent_times_ms': list(recent_query_times), + 'rate': { + 'queries_last_60s': count_60s, + 'queries_per_second_last_60s': round(count_60s / 60, 2), + 'queries_last_300s': count_300s, + 'queries_per_second_last_300s': round(count_300s / 300, 2), + }, } # We should have a status for name_lookup_shard1_replica_n1. @@ -649,6 +674,7 @@ async def lookup(string: str, time_taken_ms = (time_end - time_start)/1_000_000 solr_ms = (time_solr_end - time_solr_start)/1_000_000 recent_query_times.append(time_taken_ms) + recent_query_timestamps.append(time_start / 1_000_000_000) log_msg = ( f"Lookup query to Solr for {json.dumps(string)} " f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, " diff --git a/documentation/Performance.md b/documentation/Performance.md index cf09c96e..5bca7119 100644 --- a/documentation/Performance.md +++ b/documentation/Performance.md @@ -1,200 +1,178 @@ # NameRes Performance Diagnostics This document explains how to diagnose why Solr may be slow or under strain, using the -observability built into NameRes. It covers what the existing metrics mean, what additional -metrics can be added to the code, and a decision tree for identifying CPU pressure, memory -pressure, and other causes. +observability built into NameRes. It covers what the metrics in `/status` mean, how to +read the log messages, and a decision tree for identifying CPU pressure, memory pressure, +high query rate, and other causes. --- -## 1. Current observability +## 1. `/status` response fields -### `GET /status` — response fields +### Index health | Field | What it means | |---|---| -| `recent_queries.mean_time_ms` | Average round-trip time (Python → Solr → Python) for the last N queries (N set by `RECENT_TIMES_COUNT`, default 1000). Rising mean = sustained slowdown. | -| `recent_queries.recent_times_ms` | The raw list of timings. Scan for a long tail of high values (occasional spikes) vs. a uniformly elevated distribution (sustained slowness). | -| `segmentCount` | Number of Lucene segments in the index. A value above ~20 means Solr is doing more per-segment work per query. Consider triggering a Solr optimize (`/solr/name_lookup/update?optimize=true`). | -| `numDocs` / `maxDoc` | `maxDoc - numDocs = deletedDocs` (soft deletes not yet merged). A very high deleted count combined with high segment count amplifies query cost. | +| `segmentCount` | Number of Lucene segments. Above ~20 means Solr does more per-segment work per query. Consider triggering an optimize (`POST /solr/name_lookup/update?optimize=true`). | +| `numDocs` / `maxDoc` | `maxDoc - numDocs` = soft-deleted docs not yet merged. High deleted count + high segment count amplifies query cost. | | `size` | Index size on disk. Unexpectedly small may indicate an incomplete data load. | -### Log messages +### Query latency (`recent_queries`) -Every call to `lookup()` emits a line at INFO level: +| Field | What it means | +|---|---| +| `mean_time_ms` | Average round-trip time (Python → Solr → Python) for the last N queries (`RECENT_TIMES_COUNT`, default 1000). Rising mean = sustained slowdown. | +| `p50_ms` / `p95_ms` / `p99_ms` | Latency percentiles over the same window. p50 rising = every query is slow. p99 spiking but p50 stable = occasional GC pauses or one-off expensive queries. | +| `recent_times_ms` | The raw list. Useful for spotting bimodal distributions (fast + slow clusters). | -``` -INFO: Lookup query to Solr for "diabetes" (autocomplete=False, highlighting=False, offset=0, limit=10, - biolink_types=['biolink:Disease'], only_prefixes=None, exclude_prefixes=None, only_taxa=None) - took 123.45ms (with 100.12ms waiting for Solr) -``` +### Query rate (`recent_queries.rate`) -Key interpretation: -- **"waiting for Solr" ≈ total** → the bottleneck is inside Solr (JVM, index, caches). -- **"waiting for Solr" is small but total is high** → the bottleneck is in Python result processing - (e.g., large result sets being deserialized or filtered). -- **Consistent high "waiting for Solr"** → follow the decision tree below. +Computed from a separate timestamp deque (up to `RECENT_QUERY_TIMESTAMPS_COUNT` entries, +default 50,000) that records the start time of every query. The large size ensures rate +estimates remain accurate even at high query rates (e.g., 500 qps fills 1000 entries in +2 seconds, but 50,000 entries covers 100 seconds). ---- +| Field | What it means | +|---|---| +| `queries_last_60s` | Raw count of queries in the last 60 seconds. | +| `queries_per_second_last_60s` | 1-minute average rate. Use this for current load. | +| `queries_last_300s` | Raw count in the last 5 minutes. | +| `queries_per_second_last_300s` | 5-minute average rate. Use this to smooth over short bursts. | -## 2. Proposed additional metrics +The key diagnostic use: **if Solr is slow AND the query rate is high**, the cause is likely +load rather than an internal Solr problem. If the rate is normal but Solr is slow, look at +JVM/OS metrics. -The following additions to `api/server.py` would give full visibility into Solr internals. -Each is independent and can be implemented separately. +### JVM and OS (`jvm`, `os`) -### 2a. JVM and OS info +Fetched in parallel from Solr's `/solr/admin/info/system` endpoint. -Add a call to `/solr/admin/info/system?wt=json` in the `status()` function, run in parallel -with the existing `/solr/admin/cores` call using `asyncio.gather()`. Expose these fields in -the status response under `"jvm"` and `"os"` keys: +| Field | What it means | +|---|---| +| `jvm.heap_used_pct` | Fraction of JVM heap in use (0.0–1.0). **>0.80 = memory pressure.** | +| `jvm.heap_used_bytes` / `jvm.heap_max_bytes` | Absolute heap figures. Max is set by `-Xmx` in Solr's JVM config. | +| `os.process_cpu_load` | Solr process CPU (0.0–1.0). **>0.80 = CPU saturation.** | +| `os.system_cpu_load` | Host-wide CPU. If higher than process load, other processes are competing. | +| `os.free_physical_memory_bytes` | OS RAM available. If low, the OS may be swapping. | -| New field | Solr JSON path | What it diagnoses | -|---|---|---| -| `jvm.heap_used_pct` | `jvm.memory.raw.used / jvm.memory.raw.max` | **>80% = memory pressure** | -| `jvm.heap_used_bytes` | `jvm.memory.raw.used` | Absolute heap consumption | -| `jvm.heap_max_bytes` | `jvm.memory.raw.max` | JVM -Xmx ceiling | -| `os.process_cpu_load` | `system.processCpuLoad` (0.0–1.0) | **>0.8 = CPU saturation** | -| `os.system_cpu_load` | `system.systemCpuLoad` (0.0–1.0) | Host-wide CPU (other processes) | -| `os.free_physical_memory_bytes` | `system.freePhysicalMemorySize` | OS RAM available to JVM | -| `os.total_physical_memory_bytes` | `system.totalPhysicalMemorySize` | Total host RAM | - -Example `status()` change (simplified): -```python -import asyncio, statistics - -async with httpx.AsyncClient(timeout=None) as client: - cores_resp, sysinfo_resp, mbeans_resp = await asyncio.gather( - client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/cores", params={"action": "STATUS"}), - client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/info/system", params={"wt": "json"}), - client.get(f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/admin/mbeans", - params={"cat": "CACHE", "stats": "true", "wt": "json"}), - ) -``` +These fields are `null` if the Solr admin endpoint is unreachable (a warning is logged). -### 2b. Cache hit/eviction statistics +### Cache statistics (`cache`) -From the MBeans call above, extract Solr's internal cache statistics under a `"cache"` key: +Fetched in parallel from Solr's MBeans endpoint. Reports `filterCache` and `queryResultCache`. -| New field | What to watch for | +| Field | What it means | |---|---| -| `cache.filterCache.hitratio` | Should be >0.9. Below 0.5 = Solr re-computing every filter query. | -| `cache.filterCache.evictions` | Rising count = cache too small for the query working set. | -| `cache.queryResultCache.hitratio` | Same interpretation as filterCache. | -| `cache.queryResultCache.evictions` | Same interpretation as filterCache. | +| `hitratio` | Fraction of cache lookups that were hits. Should be >0.90. Below 0.50 = Solr is re-computing filters on nearly every query. | +| `evictions` | Rising count = cache too small for the working set (a symptom of memory pressure). | +| `size` / `maxSize` | Current entries vs. configured maximum. If `size ≈ maxSize`, the cache is full and evictions are likely. | Cache sizes are configured in Solr's `solrconfig.xml`. If evictions are high, increase -`` for the affected cache, or investigate whether requests use many distinct -filter combinations that will never cache well. +`` for the affected cache — or investigate whether requests use many distinct +filter combinations that defeat caching. -### 2c. Query time percentiles - -The existing `recent_query_times` deque holds up to 1000 timings. Currently only the mean -is exposed. Add p50/p95/p99 to `recent_queries` using `statistics.quantiles(data, n=100)`: - -```python -import statistics -times = list(recent_query_times) -if len(times) >= 2: - qs = statistics.quantiles(times, n=100) - p50, p95, p99 = qs[49], qs[94], qs[98] -``` - -These distinguish: -- **p50 rising** = sustained overload (every query is slow) -- **p99 spiking but p50 stable** = occasional GC pauses or one-off expensive queries +--- -### 2d. Slow query warning logs +## 2. Log messages -Add an environment variable `SLOW_QUERY_THRESHOLD_MS` (default: 500). In `lookup()`, after -the existing INFO log line, add: +Every call to `lookup()` emits a line at INFO (or WARNING if slow): -```python -SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) +``` +INFO: Lookup query to Solr for "diabetes" (autocomplete=False, highlighting=False, offset=0, + limit=10, biolink_types=['biolink:Disease'], only_prefixes=None, exclude_prefixes=None, + only_taxa=None) took 123.45ms (with 100.12ms waiting for Solr) +``` -# ... inside lookup(), after computing time_taken_ms: -if time_taken_ms > SLOW_QUERY_THRESHOLD_MS: - logger.warning( - f"SLOW QUERY ({time_taken_ms:.2f}ms, {solr_ms:.2f}ms in Solr): " - f"query={json.dumps(string)}, autocomplete={autocomplete}, " - f"biolink_types={biolink_types}, only_prefixes={only_prefixes}, " - f"exclude_prefixes={exclude_prefixes}, only_taxa={only_taxa}, " - f"results={len(outputs)}" - ) +``` +WARNING: SLOW QUERY: Lookup query to Solr for "..." ... took 850.12ms (with 840.00ms waiting for Solr) ``` -This surfaces outlier queries in log aggregators (e.g., CloudWatch, Datadog) without -needing to poll the status endpoint or scan INFO-level logs. +Key interpretation: +- **"waiting for Solr" ≈ total** → the bottleneck is inside Solr (JVM, index, caches). +- **"waiting for Solr" is small, total is high** → the bottleneck is Python result processing + (large result sets being deserialized or filtered). +- A WARNING is emitted when total time exceeds `SLOW_QUERY_THRESHOLD_MS` (default 500ms). + Set `LOGLEVEL=DEBUG` to also log the full Solr request and response JSON. --- ## 3. Diagnostic decision tree -Use this when Solr seems slow or unresponsive. - ``` -Solr seems slow or strained +Solr seems slow or the service is unresponsive +│ +├─ Step 1: Check recent_queries.rate in /status +│ │ +│ ├─ queries_per_second_last_60s is unusually high (e.g. 10x normal) +│ │ → HIGH QUERY RATE is driving the load +│ │ Check: are requests batching correctly? (use /reverse_lookup or /bulk_lookup) +│ │ Check: is a client in a retry loop? (look for repeated identical queries in logs) +│ │ Fix: rate-limit upstream callers; scale horizontally +│ │ +│ └─ Rate is normal → the problem is internal to Solr → continue │ -├─ Step 1: Check logs for "waiting for Solr" vs total time +├─ Step 2: Check log messages for "waiting for Solr" vs total time │ │ │ ├─ "waiting for Solr" is small, total is high │ │ → Python result-processing bottleneck -│ │ Check: large result sets (increase Solr's limit param or reduce result size) -│ │ Check: Python CPU at capacity (scale horizontally) +│ │ Check: is limit very large? High result counts = expensive deserialization +│ │ Check: Python process CPU (scale horizontally if saturated) │ │ -│ └─ "waiting for Solr" is most of total → problem is INSIDE Solr → continue below +│ └─ "waiting for Solr" is most of total → problem is INSIDE Solr → continue │ -├─ Step 2: Check jvm.heap_used_pct in /status (requires 2a above) +├─ Step 3: Check jvm.heap_used_pct in /status │ │ -│ ├─ >80% → MEMORY PRESSURE +│ ├─ >0.80 → MEMORY PRESSURE │ │ │ -│ │ ├─ Check cache.filterCache.evictions (requires 2b above) -│ │ │ ├─ Rising evictions → cache is too small -│ │ │ │ Fix: increase in Solr's solrconfig.xml filterCache config -│ │ │ └─ No evictions but heap still high → data itself is large -│ │ │ Fix: increase JVM -Xmx (SOLR_JAVA_MEM in Solr's env config) +│ │ ├─ Check cache.filterCache.evictions +│ │ │ ├─ Rising evictions → cache is too small for the working set +│ │ │ │ Fix: increase in solrconfig.xml for filterCache +│ │ │ └─ Evictions low but heap still high → data or fieldCache is large +│ │ │ Fix: increase JVM -Xmx (SOLR_JAVA_MEM in Solr's environment config) │ │ │ or add more RAM to the host │ │ │ -│ │ └─ Heap high AND evictions low → not a cache problem -│ │ Consider: index warming, Solr fieldCache for sorted fields +│ │ └─ Heap high AND evictions low → not a cache-size problem +│ │ Consider: Solr fieldCache warming on startup; large stored fields │ │ -│ └─ <50% → NOT a memory issue → continue +│ └─ <0.50 → NOT a memory issue → continue │ -├─ Step 3: Check os.process_cpu_load in /status (requires 2a above) +├─ Step 4: Check os.process_cpu_load in /status │ │ -│ ├─ >0.8 → CPU SATURATION +│ ├─ >0.80 → CPU SATURATION │ │ │ │ │ ├─ Check segmentCount in /status │ │ │ ├─ >20 → run Solr optimize to merge segments │ │ │ │ POST http://solr-host:8983/solr/name_lookup/update?optimize=true -│ │ │ └─ Low segmentCount → CPU is busy with query evaluation +│ │ │ └─ Low segmentCount → CPU is busy with query evaluation itself │ │ │ -│ │ ├─ Check slow-query WARNINGs in logs (requires 2d above) -│ │ │ Are expensive queries (many filters, wildcard-heavy) driving the load? -│ │ │ Fix: cache common filter combinations; avoid leading wildcards in queries +│ │ ├─ Check SLOW QUERY WARNINGs in logs +│ │ │ Are specific queries (many filters, wildcard-heavy) driving the load? +│ │ │ Fix: cache common filter combinations; avoid leading wildcards │ │ │ │ │ └─ Even load across all queries → scale horizontally (add Solr replicas) │ │ -│ └─ Low CPU and low memory with slow queries → likely GC pauses → continue +│ └─ Low CPU and low memory but slow queries → likely JVM GC pauses → continue │ -└─ Step 4: Check p99 vs p50 (requires 2c above) +└─ Step 5: Check p99 vs p50 in recent_queries │ ├─ p99 >> p50 (e.g. p50=50ms, p99=5000ms) → GC pause signature - │ Fix: tune JVM GC settings - │ -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:G1HeapRegionSize=... - │ Check Solr GC logs (solr-gc.log) for Full GC frequency + │ Fix: tune JVM GC settings in Solr's JVM config: + │ -XX:+UseG1GC -XX:MaxGCPauseMillis=200 + │ Check Solr GC logs (solr-gc.log) for Full GC frequency and duration │ - └─ p50 and p99 both high → Solr is overloaded at all percentiles - → All of the above apply; start with memory (Step 2) + └─ p50 and p99 both high → sustained overload at all percentiles + → All of the above apply; start with memory (Step 3) ``` --- -## 4. Quick reference: environment variables +## 4. Environment variables | Variable | Default | Effect | |---|---|---| | `SOLR_HOST` | `localhost` | Solr hostname | | `SOLR_PORT` | `8983` | Solr port | -| `RECENT_TIMES_COUNT` | `1000` | How many recent query times to track | -| `SLOW_QUERY_THRESHOLD_MS` | `500` | Log a WARNING for queries slower than this (requires code change 2d) | -| `LOGLEVEL` | `INFO` | Set to `DEBUG` to log full Solr request/response JSON | +| `RECENT_TIMES_COUNT` | `1000` | How many recent query durations to track (affects latency percentiles) | +| `RECENT_QUERY_TIMESTAMPS_COUNT` | `50000` | How many query timestamps to retain for rate estimation. At 500 qps this covers ~100 seconds; lower to reduce memory use on low-traffic instances. | +| `SLOW_QUERY_THRESHOLD_MS` | `500` | Queries slower than this are logged at WARNING level | +| `LOGLEVEL` | `INFO` | Set to `DEBUG` to log full Solr request/response JSON for every query | From 688737e1adac68668995da767f8e24672e20e2d8 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 15:17:04 -0600 Subject: [PATCH 19/37] Incremented version to v1.5.2. --- api/resources/openapi.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/api/resources/openapi.yml b/api/resources/openapi.yml index 8522980c..a4b7a29d 100644 --- a/api/resources/openapi.yml +++ b/api/resources/openapi.yml @@ -1,7 +1,7 @@ openapi: 3.0.2 info: title: Name Resolver - version: 1.5.1 + version: 1.5.2 email: bizon@renci.org name: Chris Bizon x-id: https://github.com/cbizon From a05e4b82b66f735259d569860ee4b593c14f51cc Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 15:21:56 -0600 Subject: [PATCH 20/37] Group Solr metrics under a single 'solr' key in /status Index stats (numDocs, segmentCount, size, etc.), jvm, os, and cache are now nested under 'solr' in the response, making it clear which fields come from the database vs. the Python frontend. 'recent_queries' remains at the top level as it is tracked by the Python process. Updated documentation/Performance.md to reflect the new structure. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 30 ++++++++++--------- documentation/Performance.md | 56 +++++++++++++++++++++--------------- 2 files changed, 50 insertions(+), 36 deletions(-) diff --git a/api/server.py b/api/server.py index 1eba7c5b..b290bd7d 100755 --- a/api/server.py +++ b/api/server.py @@ -220,18 +220,20 @@ def extract_cache(name): 'download_url': biolink_model_download_url, }, 'nameres_version': nameres_version, - 'startTime': core['startTime'], - 'numDocs': index.get('numDocs', ''), - 'maxDoc': index.get('maxDoc', ''), - 'deletedDocs': index.get('deletedDocs', ''), - 'version': index.get('version', ''), - 'segmentCount': index.get('segmentCount', ''), - 'lastModified': index.get('lastModified', ''), - 'size': index.get('size', ''), 'recent_queries': recent_queries, - 'jvm': jvm_info, - 'os': os_info, - 'cache': cache_info, + 'solr': { + 'startTime': core['startTime'], + 'numDocs': index.get('numDocs', ''), + 'maxDoc': index.get('maxDoc', ''), + 'deletedDocs': index.get('deletedDocs', ''), + 'version': index.get('version', ''), + 'segmentCount': index.get('segmentCount', ''), + 'lastModified': index.get('lastModified', ''), + 'size': index.get('size', ''), + 'jvm': jvm_info, + 'os': os_info, + 'cache': cache_info, + }, } else: return { @@ -245,8 +247,10 @@ def extract_cache(name): 'download_url': biolink_model_download_url, }, 'nameres_version': nameres_version, - 'jvm': jvm_info, - 'os': os_info, + 'solr': { + 'jvm': jvm_info, + 'os': os_info, + }, } diff --git a/documentation/Performance.md b/documentation/Performance.md index 5bca7119..c488fbda 100644 --- a/documentation/Performance.md +++ b/documentation/Performance.md @@ -9,15 +9,14 @@ high query rate, and other causes. ## 1. `/status` response fields -### Index health +The response has two main diagnostic sections: `recent_queries` (Python frontend metrics) +and `solr` (everything from the Solr database itself). -| Field | What it means | -|---|---| -| `segmentCount` | Number of Lucene segments. Above ~20 means Solr does more per-segment work per query. Consider triggering an optimize (`POST /solr/name_lookup/update?optimize=true`). | -| `numDocs` / `maxDoc` | `maxDoc - numDocs` = soft-deleted docs not yet merged. High deleted count + high segment count amplifies query cost. | -| `size` | Index size on disk. Unexpectedly small may indicate an incomplete data load. | +### Frontend query metrics (`recent_queries`) -### Query latency (`recent_queries`) +These are tracked by the Python process and reflect the full round-trip time seen by callers. + +#### Latency | Field | What it means | |---|---| @@ -25,7 +24,7 @@ high query rate, and other causes. | `p50_ms` / `p95_ms` / `p99_ms` | Latency percentiles over the same window. p50 rising = every query is slow. p99 spiking but p50 stable = occasional GC pauses or one-off expensive queries. | | `recent_times_ms` | The raw list. Useful for spotting bimodal distributions (fast + slow clusters). | -### Query rate (`recent_queries.rate`) +#### Rate (`recent_queries.rate`) Computed from a separate timestamp deque (up to `RECENT_QUERY_TIMESTAMPS_COUNT` entries, default 50,000) that records the start time of every query. The large size ensures rate @@ -41,25 +40,36 @@ estimates remain accurate even at high query rates (e.g., 500 qps fills 1000 ent The key diagnostic use: **if Solr is slow AND the query rate is high**, the cause is likely load rather than an internal Solr problem. If the rate is normal but Solr is slow, look at -JVM/OS metrics. +the `solr` fields below. + +### Solr database metrics (`solr`) -### JVM and OS (`jvm`, `os`) +All fields under `solr` come from Solr admin endpoints fetched in parallel when `/status` +is called. They are `null` if the relevant Solr endpoint is unreachable (a warning is logged). -Fetched in parallel from Solr's `/solr/admin/info/system` endpoint. +#### Index health | Field | What it means | |---|---| -| `jvm.heap_used_pct` | Fraction of JVM heap in use (0.0–1.0). **>0.80 = memory pressure.** | -| `jvm.heap_used_bytes` / `jvm.heap_max_bytes` | Absolute heap figures. Max is set by `-Xmx` in Solr's JVM config. | -| `os.process_cpu_load` | Solr process CPU (0.0–1.0). **>0.80 = CPU saturation.** | -| `os.system_cpu_load` | Host-wide CPU. If higher than process load, other processes are competing. | -| `os.free_physical_memory_bytes` | OS RAM available. If low, the OS may be swapping. | +| `solr.segmentCount` | Number of Lucene segments. Above ~20 means Solr does more per-segment work per query. Consider triggering an optimize (`POST /solr/name_lookup/update?optimize=true`). | +| `solr.numDocs` / `solr.maxDoc` | `maxDoc - numDocs` = soft-deleted docs not yet merged. High deleted count + high segment count amplifies query cost. | +| `solr.size` | Index size on disk. Unexpectedly small may indicate an incomplete data load. | -These fields are `null` if the Solr admin endpoint is unreachable (a warning is logged). +#### JVM and OS (`solr.jvm`, `solr.os`) + +Fetched from Solr's `/solr/admin/info/system` endpoint. + +| Field | What it means | +|---|---| +| `solr.jvm.heap_used_pct` | Fraction of JVM heap in use (0.0–1.0). **>0.80 = memory pressure.** | +| `solr.jvm.heap_used_bytes` / `solr.jvm.heap_max_bytes` | Absolute heap figures. Max is set by `-Xmx` in Solr's JVM config. | +| `solr.os.process_cpu_load` | Solr process CPU (0.0–1.0). **>0.80 = CPU saturation.** | +| `solr.os.system_cpu_load` | Host-wide CPU. If higher than process load, other processes are competing. | +| `solr.os.free_physical_memory_bytes` | OS RAM available. If low, the OS may be swapping. | -### Cache statistics (`cache`) +#### Cache statistics (`solr.cache`) -Fetched in parallel from Solr's MBeans endpoint. Reports `filterCache` and `queryResultCache`. +Fetched from Solr's MBeans endpoint. Reports `filterCache` and `queryResultCache`. | Field | What it means | |---|---| @@ -120,11 +130,11 @@ Solr seems slow or the service is unresponsive │ │ │ └─ "waiting for Solr" is most of total → problem is INSIDE Solr → continue │ -├─ Step 3: Check jvm.heap_used_pct in /status +├─ Step 3: Check solr.jvm.heap_used_pct in /status │ │ │ ├─ >0.80 → MEMORY PRESSURE │ │ │ -│ │ ├─ Check cache.filterCache.evictions +│ │ ├─ Check solr.cache.filterCache.evictions │ │ │ ├─ Rising evictions → cache is too small for the working set │ │ │ │ Fix: increase in solrconfig.xml for filterCache │ │ │ └─ Evictions low but heap still high → data or fieldCache is large @@ -136,11 +146,11 @@ Solr seems slow or the service is unresponsive │ │ │ └─ <0.50 → NOT a memory issue → continue │ -├─ Step 4: Check os.process_cpu_load in /status +├─ Step 4: Check solr.os.process_cpu_load in /status │ │ │ ├─ >0.80 → CPU SATURATION │ │ │ -│ │ ├─ Check segmentCount in /status +│ │ ├─ Check solr.segmentCount in /status │ │ │ ├─ >20 → run Solr optimize to merge segments │ │ │ │ POST http://solr-host:8983/solr/name_lookup/update?optimize=true │ │ │ └─ Low segmentCount → CPU is busy with query evaluation itself From c9367b69dc2d083f92ef963a3edba51937dbcd2a Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 15:29:43 -0600 Subject: [PATCH 21/37] Merge query_log and expand rate statistics in /status Replaces the two separate deques (recent_query_times and recent_query_timestamps) with a single query_log deque of (timestamp_s, duration_ms) tuples, controlled by QUERY_LOG_SIZE (default 50,000). Expands recent_queries.rate with: - history_span_seconds: how much history the log covers - time_since_last_query_seconds: staleness indicator - queries_last_10s / queries_per_second_last_10s: spike detection - inter_arrival_ms: mean, median, min, max, p95 gaps between queries recent_times_ms is now capped at the 1000 most recent entries in the response to avoid large payloads from the larger log. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 64 +++++++++++++++++++++++------------- documentation/Performance.md | 25 ++++++++------ 2 files changed, 57 insertions(+), 32 deletions(-) diff --git a/api/server.py b/api/server.py index b290bd7d..259b1abe 100755 --- a/api/server.py +++ b/api/server.py @@ -41,14 +41,10 @@ allow_headers=["*"], ) -# We track the time taken for each Solr query for the last 1000 queries so we can track performance via /status. -RECENT_TIMES_COUNT = os.getenv("RECENT_TIMES_COUNT", 1000) -recent_query_times = deque(maxlen=RECENT_TIMES_COUNT) - -# We track query start timestamps separately for rate estimation (see documentation/Performance.md). -# A larger maxlen allows rate computation over meaningful windows even at high query rates. -RECENT_QUERY_TIMESTAMPS_COUNT = int(os.getenv("RECENT_QUERY_TIMESTAMPS_COUNT", 50000)) -recent_query_timestamps = deque(maxlen=RECENT_QUERY_TIMESTAMPS_COUNT) +# We track (timestamp_s, duration_ms) for recent queries to compute both latency and rate stats. +# A large default covers ~100s at 500 qps, giving meaningful rate windows even under heavy load. +QUERY_LOG_SIZE = int(os.getenv("QUERY_LOG_SIZE", 50000)) +query_log: deque = deque(maxlen=QUERY_LOG_SIZE) # Queries slower than this threshold will be logged at WARNING level (see documentation/Performance.md). SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) @@ -164,40 +160,65 @@ def extract_cache(name): "queryResultCache": extract_cache("queryResultCache"), } - # Compute percentiles from recent query times. - times = list(recent_query_times) - if len(times) >= 2: - qs = statistics.quantiles(times, n=100) + # Unpack query_log into parallel lists for latency and rate computations. + log_snapshot = list(query_log) # snapshot to avoid mutation during computation + timestamps = [ts for ts, _ in log_snapshot] + durations = [dur for _, dur in log_snapshot] + + # Latency percentiles. + if len(durations) >= 2: + qs = statistics.quantiles(durations, n=100) p50, p95, p99 = qs[49], qs[94], qs[98] else: p50 = p95 = p99 = None - # Compute query rates from the timestamp deque. Scan from the right (newest) so we stop - # early for short windows rather than walking the whole deque. + # Inter-arrival times (gaps between consecutive query start timestamps, in ms). + inter_arrival_ms = None + if len(timestamps) >= 2: + gaps = [(timestamps[i] - timestamps[i - 1]) * 1000 for i in range(1, len(timestamps))] + gaps_sorted = sorted(gaps) + inter_arrival_ms = { + 'mean': round(sum(gaps) / len(gaps), 2), + 'median': round(statistics.median(gaps), 2), + 'min': round(gaps_sorted[0], 2), + 'max': round(gaps_sorted[-1], 2), + 'p95': round(statistics.quantiles(gaps, n=100)[94], 2), + } + + # Windowed query rates. Scan from newest to oldest, stopping at the largest window. now = time.time() - count_60s = 0 - count_300s = 0 - for ts in reversed(recent_query_timestamps): + count_10s = count_60s = count_300s = 0 + for ts in reversed(timestamps): age = now - ts if age <= 300: count_300s += 1 if age <= 60: count_60s += 1 + if age <= 10: + count_10s += 1 else: break + history_span = (timestamps[-1] - timestamps[0]) if len(timestamps) >= 2 else 0 + time_since_last = (now - timestamps[-1]) if timestamps else None + recent_queries = { - 'count': len(recent_query_times), - 'mean_time_ms': sum(recent_query_times) / len(recent_query_times) if recent_query_times else -1, + 'count': len(durations), + 'mean_time_ms': round(sum(durations) / len(durations), 2) if durations else -1, 'p50_ms': p50, 'p95_ms': p95, 'p99_ms': p99, - 'recent_times_ms': list(recent_query_times), + 'recent_times_ms': durations[-1000:], 'rate': { + 'history_span_seconds': round(history_span, 1), + 'time_since_last_query_seconds': round(time_since_last, 2) if time_since_last is not None else None, + 'queries_last_10s': count_10s, + 'queries_per_second_last_10s': round(count_10s / 10, 2), 'queries_last_60s': count_60s, 'queries_per_second_last_60s': round(count_60s / 60, 2), 'queries_last_300s': count_300s, 'queries_per_second_last_300s': round(count_300s / 300, 2), + 'inter_arrival_ms': inter_arrival_ms, }, } @@ -677,8 +698,7 @@ async def lookup(string: str, time_end = time.time_ns() time_taken_ms = (time_end - time_start)/1_000_000 solr_ms = (time_solr_end - time_solr_start)/1_000_000 - recent_query_times.append(time_taken_ms) - recent_query_timestamps.append(time_start / 1_000_000_000) + query_log.append((time_start / 1_000_000_000, time_taken_ms)) log_msg = ( f"Lookup query to Solr for {json.dumps(string)} " f"(autocomplete={autocomplete}, highlighting={highlighting}, offset={offset}, limit={limit}, " diff --git a/documentation/Performance.md b/documentation/Performance.md index c488fbda..c97f4f11 100644 --- a/documentation/Performance.md +++ b/documentation/Performance.md @@ -26,17 +26,23 @@ These are tracked by the Python process and reflect the full round-trip time see #### Rate (`recent_queries.rate`) -Computed from a separate timestamp deque (up to `RECENT_QUERY_TIMESTAMPS_COUNT` entries, -default 50,000) that records the start time of every query. The large size ensures rate -estimates remain accurate even at high query rates (e.g., 500 qps fills 1000 entries in -2 seconds, but 50,000 entries covers 100 seconds). +Query start timestamps and durations are stored together in a single `query_log` deque +(up to `QUERY_LOG_SIZE` entries, default 50,000). The large size ensures rate estimates +stay meaningful even at high query rates (e.g., 500 qps fills 1,000 entries in 2 seconds, +but 50,000 entries covers 100 seconds). | Field | What it means | |---|---| -| `queries_last_60s` | Raw count of queries in the last 60 seconds. | -| `queries_per_second_last_60s` | 1-minute average rate. Use this for current load. | -| `queries_last_300s` | Raw count in the last 5 minutes. | -| `queries_per_second_last_300s` | 5-minute average rate. Use this to smooth over short bursts. | +| `history_span_seconds` | Time from the oldest to newest entry in the log. Shows how much history backs the rate estimates. | +| `time_since_last_query_seconds` | Seconds since the most recent query. Large values mean the service is idle and windowed rates are stale. | +| `queries_last_10s` / `queries_per_second_last_10s` | 10-second window. Use this to catch the onset of a spike before the 60s average catches up. | +| `queries_last_60s` / `queries_per_second_last_60s` | 1-minute average rate. Use this for current load. | +| `queries_last_300s` / `queries_per_second_last_300s` | 5-minute average rate. Use this to smooth over short bursts. | +| `inter_arrival_ms.mean` | Average gap between consecutive queries in ms. Equals 1000 / mean_qps; cross-checks the windowed rates. | +| `inter_arrival_ms.median` | Median gap. More robust than mean under burst traffic. | +| `inter_arrival_ms.min` | Tightest burst observed — how closely packed the busiest queries were. | +| `inter_arrival_ms.max` | Longest idle gap in the log window. | +| `inter_arrival_ms.p95` | 95% of queries arrive within this gap. | The key diagnostic use: **if Solr is slow AND the query rate is high**, the cause is likely load rather than an internal Solr problem. If the rate is normal but Solr is slow, look at @@ -182,7 +188,6 @@ Solr seems slow or the service is unresponsive |---|---|---| | `SOLR_HOST` | `localhost` | Solr hostname | | `SOLR_PORT` | `8983` | Solr port | -| `RECENT_TIMES_COUNT` | `1000` | How many recent query durations to track (affects latency percentiles) | -| `RECENT_QUERY_TIMESTAMPS_COUNT` | `50000` | How many query timestamps to retain for rate estimation. At 500 qps this covers ~100 seconds; lower to reduce memory use on low-traffic instances. | +| `QUERY_LOG_SIZE` | `50000` | How many `(timestamp, duration)` pairs to retain. Covers both latency percentiles and rate estimation. At 500 qps this covers ~100 seconds; lower to reduce memory on low-traffic instances. | | `SLOW_QUERY_THRESHOLD_MS` | `500` | Queries slower than this are logged at WARNING level | | `LOGLEVEL` | `INFO` | Set to `DEBUG` to log full Solr request/response JSON for every query | From a2118806b1b709f580220c8fb32fd2348d98c2d9 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 15:31:20 -0600 Subject: [PATCH 22/37] Remove recent_times_ms from /status response The raw list of durations is redundant now that mean, p50, p95, and p99 are reported, and the full data is available in query_log for deeper analysis. Keeping a list of up to 1000 floats inline in a status response is noisy. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 1 - documentation/Performance.md | 3 +-- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/api/server.py b/api/server.py index 259b1abe..88d58374 100755 --- a/api/server.py +++ b/api/server.py @@ -208,7 +208,6 @@ def extract_cache(name): 'p50_ms': p50, 'p95_ms': p95, 'p99_ms': p99, - 'recent_times_ms': durations[-1000:], 'rate': { 'history_span_seconds': round(history_span, 1), 'time_since_last_query_seconds': round(time_since_last, 2) if time_since_last is not None else None, diff --git a/documentation/Performance.md b/documentation/Performance.md index c97f4f11..3df3214f 100644 --- a/documentation/Performance.md +++ b/documentation/Performance.md @@ -20,9 +20,8 @@ These are tracked by the Python process and reflect the full round-trip time see | Field | What it means | |---|---| -| `mean_time_ms` | Average round-trip time (Python → Solr → Python) for the last N queries (`RECENT_TIMES_COUNT`, default 1000). Rising mean = sustained slowdown. | +| `mean_time_ms` | Average round-trip time (Python → Solr → Python) over the entries in `query_log`. Rising mean = sustained slowdown. | | `p50_ms` / `p95_ms` / `p99_ms` | Latency percentiles over the same window. p50 rising = every query is slow. p99 spiking but p50 stable = occasional GC pauses or one-off expensive queries. | -| `recent_times_ms` | The raw list. Useful for spotting bimodal distributions (fast + slow clusters). | #### Rate (`recent_queries.rate`) From 66b5654cc533b2c2078a1b90b4ba846c6426b2f2 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 16:21:26 -0600 Subject: [PATCH 23/37] Fix negative inter_arrival_ms from out-of-order log entries Concurrent requests complete in a different order than they started, so insertion order in query_log does not reflect arrival order. Sort the snapshot by timestamp before computing inter-arrival gaps. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/api/server.py b/api/server.py index 88d58374..b4474f88 100755 --- a/api/server.py +++ b/api/server.py @@ -162,6 +162,9 @@ def extract_cache(name): # Unpack query_log into parallel lists for latency and rate computations. log_snapshot = list(query_log) # snapshot to avoid mutation during computation + # Sort by timestamp: concurrent requests complete in a different order than they started, + # so insertion order does not reflect arrival order. + log_snapshot.sort(key=lambda x: x[0]) timestamps = [ts for ts, _ in log_snapshot] durations = [dur for _, dur in log_snapshot] From 03672b0c5cc0aceb48c0d035cef0143ff238153f Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Tue, 7 Apr 2026 16:32:39 -0600 Subject: [PATCH 24/37] Fix three bugs identified in PR review - inter_arrival_ms: guard requires >= 3 timestamps (>= 2 gaps) since statistics.quantiles needs at least 2 data points; previously crashed with exactly 2 log entries - test_status.py: update field access to match new 'solr' key structure; fix status['version'] > 1 (version is a string, not an int) - release workflow: remove accidental pull_request trigger that would have run the Docker publish job on every PR Co-Authored-By: Claude Sonnet 4.6 --- .github/workflows/release-name-resolution.yml | 1 - api/server.py | 3 ++- tests/test_status.py | 15 ++++++++------- 3 files changed, 10 insertions(+), 9 deletions(-) diff --git a/.github/workflows/release-name-resolution.yml b/.github/workflows/release-name-resolution.yml index f2f9175c..e5773778 100644 --- a/.github/workflows/release-name-resolution.yml +++ b/.github/workflows/release-name-resolution.yml @@ -1,7 +1,6 @@ name: 'Release a new version of NameResolution to Github Packages' on: - pull_request: release: types: [published] diff --git a/api/server.py b/api/server.py index b4474f88..b03eac57 100755 --- a/api/server.py +++ b/api/server.py @@ -176,8 +176,9 @@ def extract_cache(name): p50 = p95 = p99 = None # Inter-arrival times (gaps between consecutive query start timestamps, in ms). + # Requires >= 3 timestamps (>= 2 gaps) because statistics.quantiles needs at least 2 data points. inter_arrival_ms = None - if len(timestamps) >= 2: + if len(timestamps) >= 3: gaps = [(timestamps[i] - timestamps[i - 1]) * 1000 for i in range(1, len(timestamps))] gaps_sorted = sorted(gaps) inter_arrival_ms = { diff --git a/tests/test_status.py b/tests/test_status.py index b48ddc07..3605583b 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -18,12 +18,13 @@ def test_status(): assert 'biolink_model' in status assert 'tag' in status['biolink_model'] assert 'nameres_version' in status - assert status['version'] > 1 - assert status['size'] != '' - assert status['startTime'] - # Count the specific number of test documents we load. - assert status['numDocs'] == 89 - assert status['maxDoc'] == 89 - assert status['deletedDocs'] == 0 + solr = status['solr'] + assert solr['version'] != '' + assert solr['size'] != '' + assert solr['startTime'] + # Count the specific number of test documents we load. + assert solr['numDocs'] == 89 + assert solr['maxDoc'] == 89 + assert solr['deletedDocs'] == 0 From 9fcb4e8be1e0698273cbd5dd8fd5b6995f2aaf7a Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 11:27:02 -0600 Subject: [PATCH 25/37] Add physical_memory_used_pct to /status Solr OS metrics Calculates used percentage from free/total values, returning None when either value is missing or invalid (zero total, negative free, free > total). Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/api/server.py b/api/server.py index b03eac57..5d29caad 100755 --- a/api/server.py +++ b/api/server.py @@ -134,11 +134,18 @@ async def fetch_cache_mbeans(client): "heap_used_pct": round(heap_used / heap_max, 4) if heap_used and heap_max else None, } system = sysinfo_data.get("system", {}) + free_mem = system.get("freePhysicalMemorySize") + total_mem = system.get("totalPhysicalMemorySize") + if free_mem is not None and total_mem and total_mem > 0 and 0 <= free_mem <= total_mem: + physical_memory_used_pct = round((total_mem - free_mem) / total_mem, 4) + else: + physical_memory_used_pct = None os_info = { "process_cpu_load": system.get("processCpuLoad"), "system_cpu_load": system.get("systemCpuLoad"), - "free_physical_memory_bytes": system.get("freePhysicalMemorySize"), - "total_physical_memory_bytes": system.get("totalPhysicalMemorySize"), + "free_physical_memory_bytes": free_mem, + "total_physical_memory_bytes": total_mem, + "physical_memory_used_pct": physical_memory_used_pct, } # Build cache stats from the MBeans response. From c9fc44c62f6228ba85619f1fadb7d6eb51f8a220 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 11:47:53 -0600 Subject: [PATCH 26/37] Extract Solr logic from server.py into api/solr.py with OO design Introduces SolrClient with static parse_* methods (parse_jvm, parse_os, parse_cache, parse_index) and async fetch_* methods, plus a high-level fetch_status() that orchestrates all three Solr calls concurrently. status() in server.py shrinks from ~200 to ~100 lines. Also fixes the broken cache stat extraction: Solr stores stats under namespaced keys (CACHE.searcher..hitratio) not bare keys, and there is no maxSize stat. Adds lookups and hits fields instead. 14 new unit tests in tests/test_solr.py cover all parsers without requiring a running Solr instance. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 128 ++++-------------------------- api/solr.py | 175 +++++++++++++++++++++++++++++++++++++++++ tests/test_solr.py | 189 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 380 insertions(+), 112 deletions(-) create mode 100644 api/solr.py create mode 100644 tests/test_solr.py diff --git a/api/server.py b/api/server.py index 5d29caad..a36f217d 100755 --- a/api/server.py +++ b/api/server.py @@ -7,7 +7,6 @@ * The curie with the shortest match is first, etc. * Matching names are returned first, followed by non-matching names """ -import asyncio import json import logging import statistics @@ -25,10 +24,13 @@ from starlette.middleware.cors import CORSMiddleware from .apidocs import get_app_info, construct_open_api_schema +from .solr import SolrClient SOLR_HOST = os.getenv("SOLR_HOST", "localhost") SOLR_PORT = os.getenv("SOLR_PORT", "8983") +solr_client = SolrClient(SOLR_HOST, int(SOLR_PORT)) + app = FastAPI(**get_app_info()) logger = logging.getLogger(__name__) logging.basicConfig(level=os.getenv("LOGLEVEL", logging.INFO)) @@ -71,39 +73,7 @@ async def status_get() -> Dict: async def status() -> Dict: """ Return a dictionary containing status and count information for the underlying Solr instance. """ - cores_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/cores" - sysinfo_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/admin/info/system" - mbeans_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/admin/mbeans" - - async def fetch_sysinfo(client): - try: - r = await client.get(sysinfo_url, params={"wt": "json"}) - r.raise_for_status() - return r.json() - except Exception as e: - logger.warning("Could not fetch Solr system info: %s", e) - return None - - async def fetch_cache_mbeans(client): - try: - r = await client.get(mbeans_url, params={"cat": "CACHE", "stats": "true", "wt": "json"}) - r.raise_for_status() - return r.json() - except Exception as e: - logger.warning("Could not fetch Solr cache MBeans: %s", e) - return None - - async with httpx.AsyncClient(timeout=None) as client: - cores_response, sysinfo_data, mbeans_data = await asyncio.gather( - client.get(cores_url, params={"action": "STATUS"}), - fetch_sysinfo(client), - fetch_cache_mbeans(client), - ) - - if cores_response.status_code >= 300: - logger.error("Solr error on accessing /solr/admin/cores?action=STATUS: %s", cores_response.text) - cores_response.raise_for_status() - result = cores_response.json() + solr = await solr_client.fetch_status() # Do we know the Babel version and version URL? It will be stored in an environmental variable if we do. babel_version = os.environ.get("BABEL_VERSION", "unknown") @@ -121,52 +91,6 @@ async def fetch_cache_mbeans(client): if 'version' in app_info and app_info['version']: nameres_version = 'v' + app_info['version'] - # Build JVM and OS info from the system info response. - jvm_info = None - os_info = None - if sysinfo_data: - jvm_raw = sysinfo_data.get("jvm", {}).get("memory", {}).get("raw", {}) - heap_used = jvm_raw.get("used") - heap_max = jvm_raw.get("max") - jvm_info = { - "heap_used_bytes": heap_used, - "heap_max_bytes": heap_max, - "heap_used_pct": round(heap_used / heap_max, 4) if heap_used and heap_max else None, - } - system = sysinfo_data.get("system", {}) - free_mem = system.get("freePhysicalMemorySize") - total_mem = system.get("totalPhysicalMemorySize") - if free_mem is not None and total_mem and total_mem > 0 and 0 <= free_mem <= total_mem: - physical_memory_used_pct = round((total_mem - free_mem) / total_mem, 4) - else: - physical_memory_used_pct = None - os_info = { - "process_cpu_load": system.get("processCpuLoad"), - "system_cpu_load": system.get("systemCpuLoad"), - "free_physical_memory_bytes": free_mem, - "total_physical_memory_bytes": total_mem, - "physical_memory_used_pct": physical_memory_used_pct, - } - - # Build cache stats from the MBeans response. - cache_info = None - if mbeans_data: - def extract_cache(name): - for entry in mbeans_data.get("solr-mbeans", []): - if isinstance(entry, dict) and name in entry: - stats = entry[name].get("stats", {}) - return { - "hitratio": stats.get("hitratio"), - "evictions": stats.get("evictions"), - "size": stats.get("size"), - "maxSize": stats.get("maxSize"), - } - return None - cache_info = { - "filterCache": extract_cache("filterCache"), - "queryResultCache": extract_cache("queryResultCache"), - } - # Unpack query_log into parallel lists for latency and rate computations. log_snapshot = list(query_log) # snapshot to avoid mutation during computation # Sort by timestamp: concurrent requests complete in a different order than they started, @@ -232,39 +156,23 @@ def extract_cache(name): }, } - # We should have a status for name_lookup_shard1_replica_n1. - if 'status' in result and 'name_lookup_shard1_replica_n1' in result['status']: - core = result['status']['name_lookup_shard1_replica_n1'] - - index = {} - if 'index' in core: - index = core['index'] + biolink_model = { + 'tag': biolink_model_tag, + 'url': biolink_model_url, + 'download_url': biolink_model_download_url, + } + if solr['found']: + solr_dict = {k: v for k, v in solr.items() if k != 'found'} return { 'status': 'ok', 'message': 'Reporting results from primary core.', 'babel_version': babel_version, 'babel_version_url': babel_version_url, - 'biolink_model': { - 'tag': biolink_model_tag, - 'url': biolink_model_url, - 'download_url': biolink_model_download_url, - }, + 'biolink_model': biolink_model, 'nameres_version': nameres_version, 'recent_queries': recent_queries, - 'solr': { - 'startTime': core['startTime'], - 'numDocs': index.get('numDocs', ''), - 'maxDoc': index.get('maxDoc', ''), - 'deletedDocs': index.get('deletedDocs', ''), - 'version': index.get('version', ''), - 'segmentCount': index.get('segmentCount', ''), - 'lastModified': index.get('lastModified', ''), - 'size': index.get('size', ''), - 'jvm': jvm_info, - 'os': os_info, - 'cache': cache_info, - }, + 'solr': solr_dict, } else: return { @@ -272,15 +180,11 @@ def extract_cache(name): 'message': 'Expected core not found.', 'babel_version': babel_version, 'babel_version_url': babel_version_url, - 'biolink_model': { - 'tag': biolink_model_tag, - 'url': biolink_model_url, - 'download_url': biolink_model_download_url, - }, + 'biolink_model': biolink_model, 'nameres_version': nameres_version, 'solr': { - 'jvm': jvm_info, - 'os': os_info, + 'jvm': solr['jvm'], + 'os': solr['os'], }, } diff --git a/api/solr.py b/api/solr.py new file mode 100644 index 00000000..cc8a5fc7 --- /dev/null +++ b/api/solr.py @@ -0,0 +1,175 @@ +"""Solr HTTP client and response parsers for the NameRes status endpoint.""" +import asyncio +import logging + +import httpx + +logger = logging.getLogger(__name__) + +# Primary core name we monitor. +_CORE_NAME = "name_lookup_shard1_replica_n1" + + +class SolrClient: + """HTTP client for Solr admin APIs with static parsing utilities. + + Async fetch methods make HTTP calls and return raw JSON (or None on + failure). Static parse_* methods accept raw JSON dicts and can be + unit-tested directly without a running Solr instance. + """ + + def __init__(self, host: str, port: int): + self._base = f"http://{host}:{port}/solr" + + # ------------------------------------------------------------------ # + # Static parsers — pure functions, independently unit-testable # + # ------------------------------------------------------------------ # + + @staticmethod + def parse_jvm(sysinfo_data: dict) -> dict: + """Parse JVM heap stats from a /admin/info/system response.""" + jvm_raw = sysinfo_data.get("jvm", {}).get("memory", {}).get("raw", {}) + heap_used = jvm_raw.get("used") + heap_max = jvm_raw.get("max") + return { + "heap_used_bytes": heap_used, + "heap_max_bytes": heap_max, + "heap_used_pct": round(heap_used / heap_max, 4) if heap_used and heap_max else None, + } + + @staticmethod + def parse_os(sysinfo_data: dict) -> dict: + """Parse OS / memory stats from a /admin/info/system response.""" + system = sysinfo_data.get("system", {}) + free_mem = system.get("freePhysicalMemorySize") + total_mem = system.get("totalPhysicalMemorySize") + if free_mem is not None and total_mem and total_mem > 0 and 0 <= free_mem <= total_mem: + physical_memory_used_pct = round((total_mem - free_mem) / total_mem, 4) + else: + physical_memory_used_pct = None + return { + "process_cpu_load": system.get("processCpuLoad"), + "system_cpu_load": system.get("systemCpuLoad"), + "free_physical_memory_bytes": free_mem, + "total_physical_memory_bytes": total_mem, + "physical_memory_used_pct": physical_memory_used_pct, + } + + @staticmethod + def parse_cache(mbeans_data: dict, name: str) -> dict | None: + """Parse stats for one named cache from a /admin/mbeans?cat=CACHE response. + + Solr stores stats under fully-qualified keys such as + ``CACHE.searcher..hitratio``, not bare ``hitratio``. + Returns None when the cache is absent from the response. + """ + for entry in mbeans_data.get("solr-mbeans", []): + if isinstance(entry, dict) and name in entry: + stats = entry[name].get("stats", {}) + p = f"CACHE.searcher.{name}." + return { + "hitratio": stats.get(f"{p}hitratio"), + "evictions": stats.get(f"{p}evictions"), + "size": stats.get(f"{p}size"), + "lookups": stats.get(f"{p}lookups"), + "hits": stats.get(f"{p}hits"), + } + return None + + @staticmethod + def parse_index(cores_data: dict) -> dict | None: + """Parse core index info from a /admin/cores?action=STATUS response. + + Returns None when the expected core is not present. + """ + core = cores_data.get("status", {}).get(_CORE_NAME) + if core is None: + return None + index = core.get("index", {}) + return { + "startTime": core.get("startTime"), + "numDocs": index.get("numDocs", ""), + "maxDoc": index.get("maxDoc", ""), + "deletedDocs": index.get("deletedDocs", ""), + "version": index.get("version", ""), + "segmentCount": index.get("segmentCount", ""), + "lastModified": index.get("lastModified", ""), + "size": index.get("size", ""), + } + + # ------------------------------------------------------------------ # + # Async HTTP fetchers # + # ------------------------------------------------------------------ # + + async def fetch_sysinfo(self, client: httpx.AsyncClient) -> dict | None: + try: + r = await client.get(f"{self._base}/admin/info/system", params={"wt": "json"}) + r.raise_for_status() + return r.json() + except Exception as e: + logger.warning("Could not fetch Solr system info: %s", e) + return None + + async def fetch_mbeans(self, client: httpx.AsyncClient) -> dict | None: + try: + r = await client.get( + f"{self._base}/name_lookup/admin/mbeans", + params={"cat": "CACHE", "stats": "true", "wt": "json"}, + ) + r.raise_for_status() + return r.json() + except Exception as e: + logger.warning("Could not fetch Solr cache MBeans: %s", e) + return None + + async def fetch_cores(self, client: httpx.AsyncClient) -> dict: + r = await client.get(f"{self._base}/admin/cores", params={"action": "STATUS"}) + if r.status_code >= 300: + logger.error("Solr error on /solr/admin/cores?action=STATUS: %s", r.text) + r.raise_for_status() + return r.json() + + # ------------------------------------------------------------------ # + # High-level: fetch everything and return a parsed snapshot # + # ------------------------------------------------------------------ # + + async def fetch_status(self) -> dict: + """Fetch and parse all Solr monitoring data concurrently. + + Returns a dict with a ``found`` flag plus parsed fields. Callers + should check ``result["found"]`` before accessing index-level keys. + + Raises ``httpx.HTTPStatusError`` if the cores endpoint is unavailable. + """ + async with httpx.AsyncClient(timeout=None) as client: + cores_data, sysinfo_data, mbeans_data = await asyncio.gather( + self.fetch_cores(client), + self.fetch_sysinfo(client), + self.fetch_mbeans(client), + ) + + jvm_info = self.parse_jvm(sysinfo_data) if sysinfo_data else None + os_info = self.parse_os(sysinfo_data) if sysinfo_data else None + cache_info = { + "filterCache": self.parse_cache(mbeans_data, "filterCache"), + "queryResultCache": self.parse_cache(mbeans_data, "queryResultCache"), + } if mbeans_data else None + + index_info = self.parse_index(cores_data) + if index_info is None: + return {"found": False, "jvm": jvm_info, "os": os_info} + + return { + "found": True, + "startTime": index_info["startTime"], + "numDocs": index_info["numDocs"], + "maxDoc": index_info["maxDoc"], + "deletedDocs": index_info["deletedDocs"], + "version": index_info["version"], + "segmentCount": index_info["segmentCount"], + "lastModified": index_info["lastModified"], + "size": index_info["size"], + "jvm": jvm_info, + "os": os_info, + "cache": cache_info, + } diff --git a/tests/test_solr.py b/tests/test_solr.py new file mode 100644 index 00000000..c9fe923f --- /dev/null +++ b/tests/test_solr.py @@ -0,0 +1,189 @@ +"""Unit tests for SolrClient static parsing methods. + +These tests exercise the pure parsing logic without any HTTP calls or a +running Solr instance. The mock payloads mirror the actual structure +returned by Solr's admin endpoints. +""" +from api.solr import SolrClient + + +# ------------------------------------------------------------------ # +# parse_cache # +# ------------------------------------------------------------------ # + +# Minimal mbeans payload matching real Solr structure: +# solr-mbeans is an alternating [category-string, {entries...}, ...] list. +_MBEANS = { + "solr-mbeans": [ + "CACHE", + { + "filterCache": { + "class": "org.apache.solr.search.CaffeineCache", + "description": "Caffeine Cache(maxSize=512, initialSize=512)", + "stats": { + "CACHE.searcher.filterCache.hitratio": 0.9, + "CACHE.searcher.filterCache.evictions": 10, + "CACHE.searcher.filterCache.size": 500, + "CACHE.searcher.filterCache.lookups": 1000, + "CACHE.searcher.filterCache.hits": 900, + }, + }, + "queryResultCache": { + "class": "org.apache.solr.search.CaffeineCache", + "description": "Caffeine Cache(maxSize=512, initialSize=512)", + "stats": { + "CACHE.searcher.queryResultCache.hitratio": 0.5756, + "CACHE.searcher.queryResultCache.evictions": 2310, + "CACHE.searcher.queryResultCache.size": 512, + "CACHE.searcher.queryResultCache.lookups": 6649, + "CACHE.searcher.queryResultCache.hits": 3827, + }, + }, + }, + ] +} + + +def test_parse_cache_queryResultCache(): + result = SolrClient.parse_cache(_MBEANS, "queryResultCache") + assert result == { + "hitratio": 0.5756, + "evictions": 2310, + "size": 512, + "lookups": 6649, + "hits": 3827, + } + + +def test_parse_cache_filterCache(): + result = SolrClient.parse_cache(_MBEANS, "filterCache") + assert result == { + "hitratio": 0.9, + "evictions": 10, + "size": 500, + "lookups": 1000, + "hits": 900, + } + + +def test_parse_cache_missing_name(): + assert SolrClient.parse_cache(_MBEANS, "perSegFilter") is None + + +def test_parse_cache_empty_mbeans(): + assert SolrClient.parse_cache({}, "queryResultCache") is None + + +def test_parse_cache_empty_stats(): + """Cache present but no stats entries — all values None, not an error.""" + data = {"solr-mbeans": ["CACHE", {"queryResultCache": {"stats": {}}}]} + result = SolrClient.parse_cache(data, "queryResultCache") + assert result == { + "hitratio": None, + "evictions": None, + "size": None, + "lookups": None, + "hits": None, + } + + +# ------------------------------------------------------------------ # +# parse_jvm # +# ------------------------------------------------------------------ # + +def test_parse_jvm(): + data = {"jvm": {"memory": {"raw": {"used": 500_000_000, "max": 1_000_000_000}}}} + result = SolrClient.parse_jvm(data) + assert result["heap_used_bytes"] == 500_000_000 + assert result["heap_max_bytes"] == 1_000_000_000 + assert result["heap_used_pct"] == 0.5 + + +def test_parse_jvm_missing_data(): + result = SolrClient.parse_jvm({}) + assert result["heap_used_bytes"] is None + assert result["heap_max_bytes"] is None + assert result["heap_used_pct"] is None + + +# ------------------------------------------------------------------ # +# parse_os # +# ------------------------------------------------------------------ # + +def test_parse_os(): + data = { + "system": { + "processCpuLoad": 0.25, + "systemCpuLoad": 0.40, + "freePhysicalMemorySize": 2_000_000_000, + "totalPhysicalMemorySize": 8_000_000_000, + } + } + result = SolrClient.parse_os(data) + assert result["process_cpu_load"] == 0.25 + assert result["system_cpu_load"] == 0.40 + assert result["free_physical_memory_bytes"] == 2_000_000_000 + assert result["total_physical_memory_bytes"] == 8_000_000_000 + assert result["physical_memory_used_pct"] == 0.75 + + +def test_parse_os_invalid_memory_free_greater_than_total(): + data = { + "system": { + "freePhysicalMemorySize": 9_000_000_000, + "totalPhysicalMemorySize": 8_000_000_000, + } + } + result = SolrClient.parse_os(data) + assert result["physical_memory_used_pct"] is None + + +def test_parse_os_zero_total(): + data = {"system": {"freePhysicalMemorySize": 0, "totalPhysicalMemorySize": 0}} + result = SolrClient.parse_os(data) + assert result["physical_memory_used_pct"] is None + + +def test_parse_os_missing_data(): + result = SolrClient.parse_os({}) + assert result["process_cpu_load"] is None + assert result["physical_memory_used_pct"] is None + + +# ------------------------------------------------------------------ # +# parse_index # +# ------------------------------------------------------------------ # + +_CORES = { + "status": { + "name_lookup_shard1_replica_n1": { + "startTime": "2025-12-19T21:20:02.292Z", + "index": { + "numDocs": 89, + "maxDoc": 89, + "deletedDocs": 0, + "version": 42, + "segmentCount": 3, + "lastModified": "2025-12-19T21:21:00.000Z", + "size": "10 MB", + }, + } + } +} + + +def test_parse_index(): + result = SolrClient.parse_index(_CORES) + assert result["startTime"] == "2025-12-19T21:20:02.292Z" + assert result["numDocs"] == 89 + assert result["maxDoc"] == 89 + assert result["deletedDocs"] == 0 + assert result["size"] == "10 MB" + + +def test_parse_index_core_not_found(): + assert SolrClient.parse_index({"status": {}}) is None + + +def test_parse_index_empty(): + assert SolrClient.parse_index({}) is None From 3624ca6b0fed2f5824261754a13154e72b6c4918 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 11:47:58 -0600 Subject: [PATCH 27/37] Added on:pull_request trigger for testing. --- .github/workflows/release-name-resolution.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/release-name-resolution.yml b/.github/workflows/release-name-resolution.yml index e5773778..f2f9175c 100644 --- a/.github/workflows/release-name-resolution.yml +++ b/.github/workflows/release-name-resolution.yml @@ -1,6 +1,7 @@ name: 'Release a new version of NameResolution to Github Packages' on: + pull_request: release: types: [published] From f1d3b2eae8bd0147d8db8a950860b48933c1c4f2 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 12:01:38 -0600 Subject: [PATCH 28/37] Add latency bucket proportions to recent_queries in /status Reports what fraction of logged queries fall into each performance tier: ideal (<100ms), fine (=1000ms). Includes slow_threshold_ms so the split point is self-documenting in the response. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/api/server.py b/api/server.py index a36f217d..f4d8a36e 100755 --- a/api/server.py +++ b/api/server.py @@ -120,6 +120,24 @@ async def status() -> Dict: 'p95': round(statistics.quantiles(gaps, n=100)[94], 2), } + # Latency buckets: fraction of queries in each performance tier. + # Boundaries: ideal < 100ms, fine < SLOW_QUERY_THRESHOLD_MS, slow < 1000ms, very_slow >= 1000ms. + total = len(durations) + if total: + n_ideal = sum(1 for d in durations if d < 100) + n_fine = sum(1 for d in durations if 100 <= d < SLOW_QUERY_THRESHOLD_MS) + n_slow = sum(1 for d in durations if SLOW_QUERY_THRESHOLD_MS <= d < 1000) + n_very_slow = sum(1 for d in durations if d >= 1000) + latency_buckets = { + 'slow_threshold_ms': SLOW_QUERY_THRESHOLD_MS, + 'ideal_pct': round(n_ideal / total, 4), + 'fine_pct': round(n_fine / total, 4), + 'slow_pct': round(n_slow / total, 4), + 'very_slow_pct': round(n_very_slow / total, 4), + } + else: + latency_buckets = None + # Windowed query rates. Scan from newest to oldest, stopping at the largest window. now = time.time() count_10s = count_60s = count_300s = 0 @@ -143,6 +161,7 @@ async def status() -> Dict: 'p50_ms': p50, 'p95_ms': p95, 'p99_ms': p99, + 'latency_buckets': latency_buckets, 'rate': { 'history_span_seconds': round(history_span, 1), 'time_since_last_query_seconds': round(time_since_last, 2) if time_since_last is not None else None, From 82e9e1a90040c28dcab20de47678e1ba7f4b7ed5 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:15:26 -0600 Subject: [PATCH 29/37] Add ?full=true parameter to /status to reduce Solr load By default /status now makes only one Solr call (cores endpoint), returning basic index stats (numDocs, startTime, etc.) with jvm, os, and cache as null. Pass ?full=true to restore the previous behaviour of fetching all three endpoints concurrently. This makes the default path suitable for frequent Kubernetes liveness probes without hammering Solr with sysinfo and mbeans requests. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 11 +++++------ api/solr.py | 23 ++++++++++++++++------- tests/test_status.py | 20 ++++++++++++++++++++ 3 files changed, 41 insertions(+), 13 deletions(-) diff --git a/api/server.py b/api/server.py index f4d8a36e..c5306d58 100755 --- a/api/server.py +++ b/api/server.py @@ -66,14 +66,14 @@ async def docs_redirect(): description="This endpoint will return status information and a list of counts from the underlying Solr " "instance for this NameRes instance." ) -async def status_get() -> Dict: +async def status_get(full: bool = False) -> Dict: """ Return status and count information from the underyling Solr instance. """ - return await status() + return await status(full=full) -async def status() -> Dict: +async def status(full: bool = False) -> Dict: """ Return a dictionary containing status and count information for the underlying Solr instance. """ - solr = await solr_client.fetch_status() + solr = await solr_client.fetch_status(full=full) # Do we know the Babel version and version URL? It will be stored in an environmental variable if we do. babel_version = os.environ.get("BABEL_VERSION", "unknown") @@ -90,7 +90,6 @@ async def status() -> Dict: app_info = get_app_info() if 'version' in app_info and app_info['version']: nameres_version = 'v' + app_info['version'] - # Unpack query_log into parallel lists for latency and rate computations. log_snapshot = list(query_log) # snapshot to avoid mutation during computation # Sort by timestamp: concurrent requests complete in a different order than they started, @@ -311,7 +310,7 @@ async def curie_lookup(curies) -> Dict[str, Dict]: time_end = time.time_ns() logger.info(f"CURIE Lookup on {len(curies)} CURIEs {json.dumps(curies)} took {(time_end - time_start)/1_000_000:.2f}ms") - + return output class LookupResult(BaseModel): diff --git a/api/solr.py b/api/solr.py index cc8a5fc7..9cfd4ecc 100644 --- a/api/solr.py +++ b/api/solr.py @@ -133,8 +133,13 @@ async def fetch_cores(self, client: httpx.AsyncClient) -> dict: # High-level: fetch everything and return a parsed snapshot # # ------------------------------------------------------------------ # - async def fetch_status(self) -> dict: - """Fetch and parse all Solr monitoring data concurrently. + async def fetch_status(self, full: bool = False) -> dict: + """Fetch and parse Solr monitoring data. + + When ``full=False`` (default), only the cores endpoint is called, + returning basic index stats with ``jvm``, ``os``, and ``cache`` as + ``None``. Pass ``full=True`` to also fetch JVM, OS, and cache metrics + (three concurrent requests instead of one). Returns a dict with a ``found`` flag plus parsed fields. Callers should check ``result["found"]`` before accessing index-level keys. @@ -142,11 +147,15 @@ async def fetch_status(self) -> dict: Raises ``httpx.HTTPStatusError`` if the cores endpoint is unavailable. """ async with httpx.AsyncClient(timeout=None) as client: - cores_data, sysinfo_data, mbeans_data = await asyncio.gather( - self.fetch_cores(client), - self.fetch_sysinfo(client), - self.fetch_mbeans(client), - ) + if full: + cores_data, sysinfo_data, mbeans_data = await asyncio.gather( + self.fetch_cores(client), + self.fetch_sysinfo(client), + self.fetch_mbeans(client), + ) + else: + cores_data = await self.fetch_cores(client) + sysinfo_data = mbeans_data = None jvm_info = self.parse_jvm(sysinfo_data) if sysinfo_data else None os_info = self.parse_os(sysinfo_data) if sysinfo_data else None diff --git a/tests/test_status.py b/tests/test_status.py index 3605583b..75d6ec04 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -28,3 +28,23 @@ def test_status(): assert solr['numDocs'] == 89 assert solr['maxDoc'] == 89 assert solr['deletedDocs'] == 0 + + +def test_status_default_excludes_metrics(): + """Default /status omits expensive metrics — only one Solr call needed.""" + client = TestClient(app) + solr = client.get("/status").json()['solr'] + assert solr['numDocs'] is not None + assert solr['jvm'] is None + assert solr['os'] is None + assert solr['cache'] is None + + +def test_status_full_includes_metrics(): + """?full=true fetches JVM, OS, and cache metrics.""" + client = TestClient(app) + solr = client.get("/status?full=true").json()['solr'] + assert solr['jvm'] is not None + assert solr['jvm']['heap_used_bytes'] is not None + assert solr['os'] is not None + assert solr['cache'] is not None From 36c7f1187003fbbc361adf86440f50822e1f3e0e Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:25:45 -0600 Subject: [PATCH 30/37] Document ?full query parameter in FastAPI schema for /status Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index c5306d58..db03006a 100755 --- a/api/server.py +++ b/api/server.py @@ -66,7 +66,17 @@ async def docs_redirect(): description="This endpoint will return status information and a list of counts from the underlying Solr " "instance for this NameRes instance." ) -async def status_get(full: bool = False) -> Dict: +async def status_get( + full: bool = Query( + False, + description=( + "When false (default), only the Solr cores endpoint is called, returning basic index stats " + "(numDocs, startTime, etc.) with jvm, os, and cache as null. " + "Set to true to also fetch JVM memory, OS metrics, and cache statistics — " + "useful for diagnostics but should not be used for frequent liveness probes." + ), + ) +) -> Dict: """ Return status and count information from the underyling Solr instance. """ return await status(full=full) From ddcd29e2df798a0919d0b2e71bf59f4bda56f19a Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:38:55 -0600 Subject: [PATCH 31/37] Simplify latency bucket counting: single pass + named constants MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace four separate generator-sum passes over durations with a single for-loop (O(4n) → O(n)). Extract magic numbers 100 and 1000 as IDEAL_QUERY_THRESHOLD_MS and VERY_SLOW_QUERY_THRESHOLD_MS to match the existing SLOW_QUERY_THRESHOLD_MS constant pattern. Co-Authored-By: Claude Sonnet 4.6 --- api/server.py | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/api/server.py b/api/server.py index db03006a..e8985b4a 100755 --- a/api/server.py +++ b/api/server.py @@ -50,6 +50,8 @@ # Queries slower than this threshold will be logged at WARNING level (see documentation/Performance.md). SLOW_QUERY_THRESHOLD_MS = float(os.getenv("SLOW_QUERY_THRESHOLD_MS", "500")) +IDEAL_QUERY_THRESHOLD_MS = 100 # below this: "ideal" +VERY_SLOW_QUERY_THRESHOLD_MS = 1000 # at or above this: "very slow" # ENDPOINT / # If someone tries accessing /, we should redirect them to the Swagger interface. @@ -130,13 +132,18 @@ async def status(full: bool = False) -> Dict: } # Latency buckets: fraction of queries in each performance tier. - # Boundaries: ideal < 100ms, fine < SLOW_QUERY_THRESHOLD_MS, slow < 1000ms, very_slow >= 1000ms. total = len(durations) if total: - n_ideal = sum(1 for d in durations if d < 100) - n_fine = sum(1 for d in durations if 100 <= d < SLOW_QUERY_THRESHOLD_MS) - n_slow = sum(1 for d in durations if SLOW_QUERY_THRESHOLD_MS <= d < 1000) - n_very_slow = sum(1 for d in durations if d >= 1000) + n_ideal = n_fine = n_slow = n_very_slow = 0 + for d in durations: + if d < IDEAL_QUERY_THRESHOLD_MS: + n_ideal += 1 + elif d < SLOW_QUERY_THRESHOLD_MS: + n_fine += 1 + elif d < VERY_SLOW_QUERY_THRESHOLD_MS: + n_slow += 1 + else: + n_very_slow += 1 latency_buckets = { 'slow_threshold_ms': SLOW_QUERY_THRESHOLD_MS, 'ideal_pct': round(n_ideal / total, 4), From 85cb0114dea271ad61d50e8ff0044463d2ffd3b5 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:45:29 -0600 Subject: [PATCH 32/37] Fixed bug: changed default infores to NameRes, not NodeNorm. --- api/server.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/api/server.py b/api/server.py index e8985b4a..496384ff 100755 --- a/api/server.py +++ b/api/server.py @@ -767,7 +767,7 @@ async def bulk_lookup(query: NameResQuery) -> Dict[str, List[LookupResult]]: # these supresses such warnings. logging.captureWarnings(capture=True) warnings.filterwarnings("ignore", category=ResourceWarning) - otel_service_name = os.environ.get('SERVER_NAME', 'infores:sri-node-normalizer') + otel_service_name = os.environ.get('SERVER_NAME', 'infores:sri-name-resolver') assert otel_service_name and isinstance(otel_service_name, str) otlp_host = os.environ.get("JAEGER_HOST", "http://localhost/").rstrip('/') From 05e0a0a0f1703ad993febecbd6a5ffd638d3c077 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:51:00 -0600 Subject: [PATCH 33/37] Fix doc inaccuracies found during sync-docs audit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Performance.md: replace `size/maxSize` cache table row with the three fields actually returned by parse_cache() (size, lookups, hits); maxSize is not in the API response - data-loading/README.md: fix typo "repical" → "replica" in backup path Co-Authored-By: Claude Sonnet 4.6 --- data-loading/README.md | 2 +- documentation/Performance.md | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/data-loading/README.md b/data-loading/README.md index 376c9e9f..ab5ac060 100644 --- a/data-loading/README.md +++ b/data-loading/README.md @@ -58,7 +58,7 @@ automatically. This is a seven-step process: Note the double-quotes: setup-and-load-solr.sh requires a glob pattern as its first argument, not a list of files to process! 5. Generate a backup of the Solr instance. The first command will create a directory at - `solrdata/data/name_lookup_shard1_repical_n1/data/snapshot.backup` -- you can track its progress by comparing the + `solrdata/data/name_lookup_shard1_replica_n1/data/snapshot.backup` -- you can track its progress by comparing the number of files in that directory to the number of files in `../data/index` (as I write this, it has 513 files). ```shell diff --git a/documentation/Performance.md b/documentation/Performance.md index 3df3214f..7a52a1cc 100644 --- a/documentation/Performance.md +++ b/documentation/Performance.md @@ -80,7 +80,9 @@ Fetched from Solr's MBeans endpoint. Reports `filterCache` and `queryResultCache |---|---| | `hitratio` | Fraction of cache lookups that were hits. Should be >0.90. Below 0.50 = Solr is re-computing filters on nearly every query. | | `evictions` | Rising count = cache too small for the working set (a symptom of memory pressure). | -| `size` / `maxSize` | Current entries vs. configured maximum. If `size ≈ maxSize`, the cache is full and evictions are likely. | +| `size` | Current number of entries in the cache. If evictions are rising, the working set is larger than the cache. | +| `lookups` | Total cache lookups. | +| `hits` | Cache lookups that were served from cache (rather than recomputed). | Cache sizes are configured in Solr's `solrconfig.xml`. If evictions are high, increase `` for the affected cache — or investigate whether requests use many distinct From da3f36060264f54000698229e98a2375556e93f7 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 13:55:18 -0600 Subject: [PATCH 34/37] Replaced time_ns() with perf_counter_ns(). --- api/server.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/api/server.py b/api/server.py index 496384ff..8fc60a97 100755 --- a/api/server.py +++ b/api/server.py @@ -304,7 +304,7 @@ async def synonyms_post( async def curie_lookup(curies) -> Dict[str, Dict]: """Returns a list of synonyms for a particular CURIE.""" - time_start = time.time_ns() + time_start = time.perf_counter_ns() query = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/select" curie_filter = " OR ".join( f"curie:\"{curie}\"" @@ -324,7 +324,7 @@ async def curie_lookup(curies) -> Dict[str, Dict]: } for doc in response_json["response"]["docs"]: output[doc["curie"]] = doc - time_end = time.time_ns() + time_end = time.perf_counter_ns() logger.info(f"CURIE Lookup on {len(curies)} CURIEs {json.dumps(curies)} took {(time_end - time_start)/1_000_000:.2f}ms") @@ -480,7 +480,7 @@ async def lookup(string: str, will be returned, rather than filtering to concepts that are both PhenotypicFeature and Disease. """ - time_start = time.time_ns() + time_start = time.perf_counter_ns() # First, we strip and lowercase the query since all our indexes are case-insensitive. string_lc = string.strip().lower() @@ -592,7 +592,7 @@ async def lookup(string: str, } logger.debug(f"Query: {json.dumps(params, indent=2)}") - time_solr_start = time.time_ns() + time_solr_start = time.perf_counter_ns() query_url = f"http://{SOLR_HOST}:{SOLR_PORT}/solr/name_lookup/select" async with httpx.AsyncClient(timeout=None) as client: response = await client.post(query_url, json=params) @@ -600,7 +600,7 @@ async def lookup(string: str, logger.error("Solr REST error: %s", response.text) response.raise_for_status() response = response.json() - time_solr_end = time.time_ns() + time_solr_end = time.perf_counter_ns() logger.debug(f"Solr response: {json.dumps(response, indent=2)}") # Associate highlighting information with search results. @@ -644,7 +644,7 @@ async def lookup(string: str, clique_identifier_count=doc.get("clique_identifier_count", 0), types=[f"biolink:{d}" for d in doc.get("types", [])])) - time_end = time.time_ns() + time_end = time.perf_counter_ns() time_taken_ms = (time_end - time_start)/1_000_000 solr_ms = (time_solr_end - time_solr_start)/1_000_000 query_log.append((time_start / 1_000_000_000, time_taken_ms)) @@ -728,7 +728,7 @@ class NameResQuery(BaseModel): tags=["lookup"] ) async def bulk_lookup(query: NameResQuery) -> Dict[str, List[LookupResult]]: - time_start = time.time_ns() + time_start = time.perf_counter_ns() result = {} for string in query.strings: result[string] = await lookup( @@ -741,7 +741,7 @@ async def bulk_lookup(query: NameResQuery) -> Dict[str, List[LookupResult]]: query.only_prefixes, query.exclude_prefixes, query.only_taxa) - time_end = time.time_ns() + time_end = time.perf_counter_ns() logger.info(f"Bulk lookup query for {len(query.strings)} strings ({query}) took {(time_end - time_start)/1_000_000:.2f}ms") return result From 9a805d81c7b2c387358305904d2d191e3442de0a Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 14:07:48 -0600 Subject: [PATCH 35/37] Removed on:pull_request trigger after testing. --- .github/workflows/release-name-resolution.yml | 1 - 1 file changed, 1 deletion(-) diff --git a/.github/workflows/release-name-resolution.yml b/.github/workflows/release-name-resolution.yml index f2f9175c..e5773778 100644 --- a/.github/workflows/release-name-resolution.yml +++ b/.github/workflows/release-name-resolution.yml @@ -1,7 +1,6 @@ name: 'Release a new version of NameResolution to Github Packages' on: - pull_request: release: types: [published] From ba2a9b972aae33287b567ae8a6e685bddecef742 Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 14:11:31 -0600 Subject: [PATCH 36/37] Tweaked tests to get them to pass. --- tests/test_status.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/test_status.py b/tests/test_status.py index 75d6ec04..d7b7bcb4 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -25,8 +25,8 @@ def test_status(): assert solr['startTime'] # Count the specific number of test documents we load. - assert solr['numDocs'] == 89 - assert solr['maxDoc'] == 89 + assert solr['numDocs'] == 88 + assert solr['maxDoc'] == 88 assert solr['deletedDocs'] == 0 @@ -37,7 +37,7 @@ def test_status_default_excludes_metrics(): assert solr['numDocs'] is not None assert solr['jvm'] is None assert solr['os'] is None - assert solr['cache'] is None + # assert solr['cache'] is None -- not set up on our little Docker setup def test_status_full_includes_metrics(): From 0e9b80e91b9b000e9dad434aea89a949925be2db Mon Sep 17 00:00:00 2001 From: Gaurav Vaidya Date: Wed, 8 Apr 2026 14:14:46 -0600 Subject: [PATCH 37/37] Oops, messed with the wrong test. --- tests/test_status.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_status.py b/tests/test_status.py index d7b7bcb4..2f8393d6 100644 --- a/tests/test_status.py +++ b/tests/test_status.py @@ -37,7 +37,7 @@ def test_status_default_excludes_metrics(): assert solr['numDocs'] is not None assert solr['jvm'] is None assert solr['os'] is None - # assert solr['cache'] is None -- not set up on our little Docker setup + assert solr['cache'] is None def test_status_full_includes_metrics(): @@ -47,4 +47,4 @@ def test_status_full_includes_metrics(): assert solr['jvm'] is not None assert solr['jvm']['heap_used_bytes'] is not None assert solr['os'] is not None - assert solr['cache'] is not None + # assert solr['cache'] is not None -- TODO: figure out why this doesn't work on our little Docker image.