Merging Performance Metrics to Prod

.env.example

@@ -5,6 +5,8 @@ OpenSearchDomainEndpoint=
 SearchOpenSearchRequestTimeoutMs=20000
 SearchRequestDeadlineMs=30000
 SearchReadinessTimeoutMs=5000
+SearchLogPerformanceTimings=false
+SearchPerformanceTelemetryIntervalMs=10000
 RequestLogSuccessSampleRate=0.1
 RequestLogHealthChecks=false
 WebSearchEnabled=true

README.md

@@ -11,6 +11,8 @@ Rename `.env.example` to `.env` and replace or check the following values.
 - `SearchOpenSearchRequestTimeoutMs` - optional timeout for each OpenSearch request, default `20000`
 - `SearchRequestDeadlineMs` - optional overall `/search` processing deadline, default `30000`
 - `SearchReadinessTimeoutMs` - optional timeout for the OpenSearch index readiness check, default `5000`
+- `SearchLogPerformanceTimings` - optional aggregate `/search` performance telemetry flag, default `false`
+- `SearchPerformanceTelemetryIntervalMs` - optional telemetry aggregation interval, default `10000` and minimum `1000`
 - `RequestLogSuccessSampleRate` - optional fraction of successful non-health-check access logs to retain, default `0.1`
 - `RequestLogHealthChecks` - optional flag to retain successful health-check access logs, default `false`
 - `WebSearchEnabled` - optional `/webSearch` availability flag, default `true`
@@ -272,6 +274,12 @@ Every request receives an `X-Request-ID` response header. A caller-provided `X-R
 
 Access logs omit query strings and request bodies. By default, the API retains 10% of successful non-health-check access logs, suppresses successful `/api/health-check` and `/api/ready-check` access logs, and retains every HTTP 4xx or 5xx access log. Set `RequestLogSuccessSampleRate` from `0` through `1` to change successful-request sampling. Set `RequestLogHealthChecks=true` to retain successful health-check logs.
 
+Set `SearchLogPerformanceTimings=true` during controlled performance diagnostics to emit one structured `search_performance_summary` JSON event per active aggregation interval. The interval defaults to 10 seconds and can be changed with `SearchPerformanceTelemetryIntervalMs`; values below 1 second fall back to the default. Telemetry is disabled by default and does not record request bodies, filter values, credentials, or returned records.
+
+Each event reports process memory and CPU, event-loop delay and utilization, searches started and completed during the interval, searches still active at its end, maximum in-flight searches, and measurements grouped by search type. Starts and completions are separate because a search can cross an interval boundary. `processCpu.percentOfOneCore` measures the process's CPU time relative to one fully occupied core and can exceed 100 when native work uses multiple cores. Direct searches report `standardOpenSearchMs`. Semantic searches report `candidateOpenSearchMs`, `candidateCount`, `postFilterMs`, `matchedCandidateCount`, and `pageFetchOpenSearchMs` when a page fetch is required. The corresponding `standardOpenSearchTookMs`, `candidateOpenSearchTookMs`, and `pageFetchOpenSearchTookMs` measurements contain OpenSearch's server-reported `took` values, allowing them to be compared with API wall-clock durations. Every completed search reports `totalRequestMs` and an outcome such as `success`, `timeout`, `client_disconnected`, `opensearch_unavailable`, or `upstream_error`. Each measurement includes its count, sampled count, average, minimum, p50, p95, p99, and maximum for the interval. Average, minimum, and maximum use every observation; percentile calculation uses a bounded reservoir of at most 2,000 observations per measurement and interval.
+
+Use these fields together when diagnosing load behavior. If an OpenSearch wall-clock measurement and its corresponding `TookMs` measurement rise together, execution or queueing inside OpenSearch is contributing to latency. If wall time rises while `TookMs` remains stable, transport or application-side waiting is contributing. Growth in `postFilterMs` and event-loop delay indicates application-side semantic processing pressure; growth in `activeRequests` with stage timings stable indicates waiting elsewhere in the request lifecycle. Summaries describe one Node process, so aggregate events from every ECS task log stream before comparing `startedRequests` with the external load generator's delivered request count. Correlate each event's timestamps with load-balancer, ECS, and OpenSearch metrics, then disable telemetry after the controlled run.
+
 Each `/search` request owns a lifecycle cancellation signal. When its overall deadline expires, the API aborts the active OpenSearch transport request before returning HTTP 504. When the caller disconnects, the API aborts work that is needed only by that caller and does not attempt to write a response. This prevents timed-out or abandoned standard searches from continuing until the transport timeout.
 
 ### Semantic Post-Filtering
@@ -287,7 +295,7 @@ The reported total and pagination are complete only within that bounded candidat
 
 `/search` orders OpenSearch results by CVE ID so repeated shallow-page requests use a deterministic sort. The response `pageSize` preserves the requested `resultsPerPage` value, while `resultsReturned` reports the number of records actually returned and may be smaller for a partial or out-of-range page. A stable sort does not provide a point-in-time snapshot, so index updates between separate page requests can still shift results until PIT-based pagination is implemented.
 
-The API does not cache, coalesce, queue, or rate-limit searches in process. Each request executes its own required OpenSearch operations. Public rate enforcement, admission control, shared caching, and performance telemetry must be supplied by the deployment infrastructure when those capabilities are enabled.
+The API does not cache, coalesce, queue, or rate-limit searches in process. Each request executes its own required OpenSearch operations. Public rate enforcement, admission control, shared caching, and durable metrics collection must be supplied by the deployment infrastructure. The optional aggregate telemetry described above writes diagnostic events to standard output for collection by the deployment logging system.
 
 OpenSearch operations use one attempt and return a sanitized HTTP 504 `SEARCH_TIMEOUT` response when they exceed the 20-second default timeout. The same response is returned when a `/search` request exceeds the 30-second default overall deadline, and the active OpenSearch request is aborted.
 

config/custom-environment-variables.jsonc

@@ -13,7 +13,9 @@
             "allowUnknownSslCerts": "OpenSearchAllowUnknownSslCerts",
             "openSearchRequestTimeoutMs": "SearchOpenSearchRequestTimeoutMs",
             "requestDeadlineMs": "SearchRequestDeadlineMs",
-            "readinessTimeoutMs": "SearchReadinessTimeoutMs"
+            "readinessTimeoutMs": "SearchReadinessTimeoutMs",
+            "performanceTelemetryEnabled": "SearchLogPerformanceTimings",
+            "performanceTelemetryIntervalMs": "SearchPerformanceTelemetryIntervalMs"
         },
         "requestLogging": {
             "successSampleRate": "RequestLogSuccessSampleRate",

config/default.jsonc

@@ -17,7 +17,11 @@
             // Limits total processing time for a /search request.
             "requestDeadlineMs": "30000",
             // Limits the minimal OpenSearch request used by /api/ready-check.
-            "readinessTimeoutMs": "5000"
+            "readinessTimeoutMs": "5000",
+            // Emits aggregate search-stage timing summaries for controlled diagnostics.
+            "performanceTelemetryEnabled": "FALSE",
+            // Controls how often enabled performance summaries are emitted.
+            "performanceTelemetryIntervalMs": "10000"
         },
         // Access logging settings. Error responses are always logged.
         "requestLogging": {

config/runtime-config.test.js

@@ -91,6 +91,10 @@ describe('runtime container and compose configuration', () => {
         );
         expect(customEnvironmentVariables).toContain('"requestDeadlineMs": "SearchRequestDeadlineMs"');
         expect(customEnvironmentVariables).toContain('"readinessTimeoutMs": "SearchReadinessTimeoutMs"');
+        expect(customEnvironmentVariables).toContain('"performanceTelemetryEnabled": "SearchLogPerformanceTimings"');
+        expect(customEnvironmentVariables).toContain(
+            '"performanceTelemetryIntervalMs": "SearchPerformanceTelemetryIntervalMs"'
+        );
         expect(customEnvironmentVariables).toContain('"successSampleRate": "RequestLogSuccessSampleRate"');
         expect(customEnvironmentVariables).toContain('"healthChecks": "RequestLogHealthChecks"');
         expect(customEnvironmentVariables).toContain('"webSearchEnabled": "WebSearchEnabled"');

controllers/searchController.js

@@ -4,6 +4,7 @@ const searchDeadline = require('../utils/searchDeadline');
 const searchProvider = require('../utils/searchProvider');
 const searchQueryBuilder = require('../utils/searchQueryBuilder');
 const searchPostFilters = require('../utils/searchPostFilters');
+const searchPerformanceTelemetry = require('../utils/searchPerformanceTelemetry');
 const error = new errors.errors();
 const openSearchUnavailableErrorNames = new Set(['ConnectionError', 'NoLivingConnectionsError']);
 const openSearchUnavailableStatusCodes = new Set([502, 503, 504]);
@@ -119,36 +120,45 @@ async function executeOpenSearch(body, signal) {
     return searchProvider.searchOpenSearch(body, { signal });
 }
 
-async function executeStandardSearch(searchOptions, queryStringObjects, signal) {
+async function executeStandardSearch(searchOptions, queryStringObjects, signal, telemetry) {
     const body = searchQueryBuilder.buildOpenSearchBody(searchOptions, queryStringObjects);
-    const searchData = await executeOpenSearch(body, signal);
+    const searchData = await telemetry.measureAsync('standardOpenSearchMs', () => executeOpenSearch(body, signal));
+    telemetry.recordValue('standardOpenSearchTookMs', searchData?.took);
 
     return {
         status: 'ok',
         data: searchData
     };
 }
 
-async function fetchFullHitsByCveIds(cveIds, signal) {
+async function fetchFullHitsByCveIds(cveIds, signal, telemetry) {
     if (!cveIds.length) return { hits: [], took: undefined };
 
     const { searchOptions, queryStringObjects } = searchQueryBuilder.buildCveIdsSearchRequest(cveIds);
     const body = searchQueryBuilder.buildOpenSearchBody(searchOptions, queryStringObjects);
-    const pageData = await executeOpenSearch(body, signal);
+    const pageData = await telemetry.measureAsync('pageFetchOpenSearchMs', () => executeOpenSearch(body, signal));
+    telemetry.recordValue('pageFetchOpenSearchTookMs', pageData?.took);
 
     return {
         hits: orderHitsByCveIds(pageData?.hits?.hits ?? [], cveIds),
         took: pageData?.took
     };
 }
 
-async function buildPostFilterCandidateResult(candidateBody, postFilters, signal) {
-    const candidateData = await executeOpenSearch(candidateBody, signal);
+async function buildPostFilterCandidateResult(candidateBody, postFilters, signal, telemetry) {
+    const candidateData = await telemetry.measureAsync('candidateOpenSearchMs', () =>
+        executeOpenSearch(candidateBody, signal)
+    );
+    telemetry.recordValue('candidateOpenSearchTookMs', candidateData?.took);
 
     const candidateResp = {
         data: candidateData
     };
-    const { filteredHits } = searchPostFilters.filterSearchHits(candidateResp, postFilters);
+    const { candidateCount, filteredHits } = telemetry.measureSync('postFilterMs', () =>
+        searchPostFilters.filterSearchHits(candidateResp, postFilters)
+    );
+    telemetry.recordValue('candidateCount', candidateCount);
+    telemetry.recordValue('matchedCandidateCount', filteredHits.length);
 
     return {
         filteredCount: filteredHits.length,
@@ -157,18 +167,25 @@ async function buildPostFilterCandidateResult(candidateBody, postFilters, signal
     };
 }
 
-async function executePostFilterSearch(searchOptions, queryStringObjects, postFilters, responseOptions, signal) {
+async function executePostFilterSearch(
+    searchOptions,
+    queryStringObjects,
+    postFilters,
+    responseOptions,
+    signal,
+    telemetry
+) {
     const candidateBody = searchQueryBuilder.buildPostFilterCandidateSearchBody(
         searchOptions,
         queryStringObjects,
         postFilters
     );
-    const candidateResult = await buildPostFilterCandidateResult(candidateBody, postFilters, signal);
+    const candidateResult = await buildPostFilterCandidateResult(candidateBody, postFilters, signal, telemetry);
     searchDeadline.throwIfAborted(signal);
     const pageCveIds = paginateHits(candidateResult.filteredCveIds, responseOptions);
     const filteredCount = candidateResult.filteredCount ?? candidateResult.filteredCveIds.length;
 
-    const pageResult = await fetchFullHitsByCveIds(pageCveIds, signal);
+    const pageResult = await fetchFullHitsByCveIds(pageCveIds, signal, telemetry);
     const response = {
         status: 'ok',
         data: {
@@ -185,12 +202,12 @@ async function executePostFilterSearch(searchOptions, queryStringObjects, postFi
     return buildPagedSearchResponse(response, filteredCount, pageResult.hits);
 }
 
-async function executeSearch(searchOptions, queryStringObjects, postFilters, responseOptions, signal) {
+async function executeSearch(searchOptions, queryStringObjects, postFilters, responseOptions, signal, telemetry) {
     if (!searchPostFilters.hasSearchPostFilters(postFilters)) {
-        return executeStandardSearch(searchOptions, queryStringObjects, signal);
+        return executeStandardSearch(searchOptions, queryStringObjects, signal, telemetry);
     }
 
-    return executePostFilterSearch(searchOptions, queryStringObjects, postFilters, responseOptions, signal);
+    return executePostFilterSearch(searchOptions, queryStringObjects, postFilters, responseOptions, signal, telemetry);
 }
 
 async function searchHandler(req, res, next) {
@@ -200,19 +217,23 @@ async function searchHandler(req, res, next) {
         res,
         searchProvider.getSearchRequestDeadlineMs()
     );
+    const telemetry = searchPerformanceTelemetry.startSearchTelemetry();
+    let telemetryOutcome = 'success';
 
     try {
         const searchRequest = searchQueryBuilder.buildSearchRequest(params);
         const searchOptions = searchRequest.searchOptions;
         const postFilters = searchRequest.postFilters;
         const responseOptions = searchRequest.responseOptions;
+        telemetry.setSearchType(postFilters);
 
         const resp = await executeSearch(
             searchOptions,
             searchRequest.queryStringObjects,
             postFilters,
             responseOptions,
-            lifecycle.signal
+            lifecycle.signal,
+            telemetry
         );
         lifecycle.throwIfAborted();
         const pagingOptions = responseOptions ?? searchOptions;
@@ -233,21 +254,26 @@ async function searchHandler(req, res, next) {
         });
     } catch (err) {
         if (searchDeadline.isSearchClientDisconnectedError(err)) {
+            telemetryOutcome = 'client_disconnected';
             return;
         }
 
         if (searchDeadline.isSearchTimeoutError(err)) {
+            telemetryOutcome = 'timeout';
             return res.status(504).json(error.searchTimeoutError());
         }
 
         if (isOpenSearchUnavailableError(err)) {
+            telemetryOutcome = 'opensearch_unavailable';
             if (typeof res.set === 'function') res.set('Retry-After', '5');
 
             return res.status(503).json(error.openSearchError());
         }
 
+        telemetryOutcome = 'upstream_error';
         return res.status(502).json(error.upstreamSearchError());
     } finally {
+        telemetry.complete(telemetryOutcome);
         lifecycle.complete();
     }
 }