feat(search): add search request observation logs and result metrics - #501
feat(search): add search request observation logs and result metrics#501eguguchkin wants to merge 3 commits into
Conversation
🔴 Performance DegradationSome benchmarks have degraded compared to the previous run. Show table
|
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## main #501 +/- ##
==========================================
- Coverage 71.33% 71.23% -0.10%
==========================================
Files 233 234 +1
Lines 18999 19108 +109
==========================================
+ Hits 13552 13612 +60
- Misses 4419 4455 +36
- Partials 1028 1041 +13 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
🔴 Performance DegradationSome benchmarks have degraded compared to the previous run. Show table
|
| if retErr != nil { | ||
| fields = append(fields, zap.NamedError("error", retErr)) | ||
| } | ||
| logger.Info("search request stat", fields...) |
There was a problem hiding this comment.
{"level":"info","ts":"2026-08-19T13:24:51.249+0300","message":"search request stat","method":"ComplexSearch","agg":false,"hist":false,"docs":100,"tier":"hot","hot_duration":0.031910833,"total_search_duration":0.033224184,"fetch_duration":0,"total_duration":0.033482858,"result":"success"}
It's not possible to correlate the incoming search request and the result. I.e. if we don't log the request itlsef as well, then it looks like we just duplicate telemetry in logs. Some of that telemetry we have already deleted (like bulk stats) as far as I remember.
| zap.Int("docs", o.stats.Size), | ||
| zap.String("tier", tier), | ||
| zap.Duration("hot_duration", o.stats.HotSearchDuration), | ||
| zap.Duration("total_search_duration", o.stats.TotalSearchDuration), |
There was a problem hiding this comment.
it looks like total_search_duration is always 0 if it's search error:
{"level":"info","ts":"2026-08-19T13:28:51.822+0300","message":"search request stat","method":"ComplexSearch","agg":true,"hist":false,"docs":10,"tier":"hot","hot_duration":0.002872493,"total_search_duration":0,"fetch_duration":0,"total_duration":0.002891408,"result":"server_error","error":"rpc error: code = Internal desc = store forbids aggregation request: aggregation has too many fraction tokens"}
There was a problem hiding this comment.
btw just noticed there are parameters total_search_duration and total_duration, hard to tell how they are different without reading the code
| zap.String("method", method), | ||
| zap.Bool("agg", o.stats.HasAgg), | ||
| zap.Bool("hist", o.stats.HasHist), | ||
| zap.Int("docs", o.stats.Size), |
There was a problem hiding this comment.
nit: If I don't look at the corresponding code, it looks like docs name is ambiguos. It's actually a size parameter of the incoming reuqest, but some might expected it to be the actual search result count (like found docs).
| type requestObservation struct { | ||
| start time.Time | ||
| fetchStart time.Time | ||
| fetchDuration time.Duration |
There was a problem hiding this comment.
nit: a liitle bit unclear with this field. This observation is not enabled for Fetch operation, yet in logs we have fetch_duration logged.
There was a problem hiding this comment.
strangely for Export operation I also hit fetch_duration equal to 0
| searchResultSuccess = "success" | ||
| searchResultClientErr = "client_error" | ||
| searchResultServerErr = "server_error" | ||
| searchResultTimeout = "timeout" |
There was a problem hiding this comment.
just a note: this "timeout" is only possible when store is timed out (we got context canceled from store). If a user presses Ctrl+C it's also a context canceled but we have server_error logged.
{"level":"info","ts":"2026-08-19T14:19:13.880+0300","message":"search request stat","method":"ComplexSearch","agg":false,"hist":false,"docs":100,"tier":"hot","hot_duration":0.822881595,"total_search_duration":0,"fetch_duration":0,"total_duration":0.822918864,"result":"server_error","error":"rpc error: code = Internal desc = rpc error: code = Canceled desc = context canceled"}
4 participants
Description
This change adds request-level observability to the search path and refactors the way search execution statistics are propagated from the ingestor to the gRPC handlers.
Observability
requestObservation(proxyapi/request_observation.go) that collects timing and storage-tier data for a single search request. It is populated indoSearchand finalized viaobs.finish(method, retErr)from each handler'sdeferred call — after the document stream has been consumed, so the recorded
total_durationincludes stream reading.search request statlog line per request withmethod,agg/histflags,docscount, storagetier, and per-phase durations (hot_duration,cold_duration,total_search_duration,fetch_duration,total_duration), plus theresultcategory and error.seq_db_ingestor_search_results_totalPrometheus counter (metric/ingestor.go) labeled byresultandtier.success/client_error/server_error/timeoutviaclassifySearchResult. The raw ingestor error is preserved separately (rawErr) so timeouts — whichprocessSearchErrorswraps intocodes.Internal— are still detected.SearchStatsrefactorIngestor.Searchnow returns*search.SearchStatsinstead of a bareoverallDuration.SearchStatscarries size, agg/hist flags, storage tier (hot/cold/none), and hot/cold/total search durations. TheSearchIngestorinterface andits mock are updated accordingly.
doSearchreturns therequestObservationalongside the response; all handlers (Search,StreamSearch,Export,Fetch, aggregations, histogram) wire up adefer obs.finish(...)and a namedretErrreturn.Streaming helpers
search.DocsIteratorSeq, aniter.Seq2[StreamingDoc, error]adapter, used to replace manualNext()loops inStreamSearchandExport.SetDocsIteratorEventsto hookonStart/onFinishcallbacks onto aDocsIterator, used to measure the actual document fetch duration (from firstNext()to stream end/EOF) independently of the ingestor-side search duration.Merged stream balance
newNMergedStreamsnow builds a balanced binary merge tree (split-in-half recursion) instead of a left-leaning chain, producing more even merge depth across input streams.Tests
doSearch/Searchsignatures and theDocsIteratorSeqiteration pattern.