diff --git a/quickwit/quickwit-common/src/tracing_utils.rs b/quickwit/quickwit-common/src/tracing_utils.rs index c39686442db..6a57b0d0e4b 100644 --- a/quickwit/quickwit-common/src/tracing_utils.rs +++ b/quickwit/quickwit-common/src/tracing_utils.rs @@ -90,6 +90,15 @@ pub fn set_current_span_parent_from_metadata(metadata: &MetadataMap) { let _ = Span::current().set_parent(parent_context); } +/// Records an attribute on the currently-active span's OpenTelemetry span. +/// +/// Unlike a `tracing` field (`#[instrument(fields(...))]` or `Span::record`), this does +/// not propagate to log events, so it can carry verbose values (e.g. a query AST) +/// without bloating logs. No-op when no OpenTelemetry layer is installed. +pub fn record_current_span_attribute(key: &'static str, value: impl Into) { + Span::current().set_attribute(key, value); +} + /// Tonic interceptor that injects the active span's W3C trace context into /// the outgoing gRPC metadata. Drop-in replacement for the legacy /// `quickwit_proto::SpanContextInterceptor`. diff --git a/quickwit/quickwit-search/src/leaf.rs b/quickwit/quickwit-search/src/leaf.rs index ec4f621b313..62eea59f526 100644 --- a/quickwit/quickwit-search/src/leaf.rs +++ b/quickwit/quickwit-search/src/leaf.rs @@ -300,7 +300,6 @@ async fn run_cancellable( /// /// Returns whether the query is provably empty in this split (i.e. `on_absent` fired and /// warmup was short-circuited). -#[instrument(skip_all)] pub(crate) async fn warmup( searcher: &Searcher, warmup_info: &WarmupInfo, @@ -746,6 +745,11 @@ async fn leaf_search_single_split( warmup_info.simplify(); let warmup_start = Instant::now(); + // Baseline the counters so the warmup span attributes exclude bytes fetched while + // opening the index (e.g. the split footer on a cold cache), which land in these same + // counters before warmup begins. + let cache_bytes_before_warmup = byte_range_cache.get_num_bytes(); + let downloaded_bytes_before_warmup = download_counters.snapshot().0; leaf_search_state_guard.set_state(SplitSearchState::WarmUp); // Negative cache: a split is provably empty for this query if any required term has // previously been proven absent here. Absence is an immutable, query- and @@ -779,7 +783,35 @@ async fn leaf_search_single_split( HitSet::empty(), ); }; - warmup(&searcher, &warmup_info, &record_absence).await? + // `warmup_mb` is warmed into the byte-range cache during warmup; `downloaded_mb` is + // the subset actually fetched from object storage (cache hits excluded). Both are + // deltas since `warmup_start`, so index-open reads are not attributed here, and are + // recorded after warmup, before the search adds to either. + const BYTES_PER_MB: f64 = 1_000_000.0; + let warmup_span = info_span!( + "warmup", + warmup_mb = tracing::field::Empty, + downloaded_mb = tracing::field::Empty + ); + let provably_empty = warmup(&searcher, &warmup_info, &record_absence) + .instrument(warmup_span.clone()) + .await?; + warmup_span.record( + "warmup_mb", + byte_range_cache + .get_num_bytes() + .saturating_sub(cache_bytes_before_warmup) as f64 + / BYTES_PER_MB, + ); + warmup_span.record( + "downloaded_mb", + download_counters + .snapshot() + .0 + .saturating_sub(downloaded_bytes_before_warmup) as f64 + / BYTES_PER_MB, + ); + provably_empty }; let warmup_end = Instant::now(); let warmup_duration: Duration = warmup_end.duration_since(warmup_start); diff --git a/quickwit/quickwit-search/src/root.rs b/quickwit/quickwit-search/src/root.rs index d5ecc589835..4d2bf9ec001 100644 --- a/quickwit/quickwit-search/src/root.rs +++ b/quickwit/quickwit-search/src/root.rs @@ -1312,8 +1312,9 @@ pub async fn root_search( let num_docs: usize = split_metadatas.iter().map(|split| split.num_docs).sum(); let num_splits = split_metadatas.len(); - // It would have been nice to add those in the context of the trace span, - // but with our current logging setting, it makes logs too verbose. + // These would bloat the logs if added as tracing span fields (they propagate to + // every log event in the span), so they go on a one-shot `info!` for logs and, via + // `record_current_span_attribute`, on the OpenTelemetry span only for the trace. info!( query_ast = search_request.query_ast.as_str(), agg = search_request.aggregation_request(), @@ -1323,6 +1324,24 @@ pub async fn root_search( num_splits = num_splits, "root_search" ); + quickwit_common::tracing_utils::record_current_span_attribute( + "query_ast", + search_request.query_ast.clone(), + ); + quickwit_common::tracing_utils::record_current_span_attribute("num_docs", num_docs as i64); + quickwit_common::tracing_utils::record_current_span_attribute("num_splits", num_splits as i64); + if let Some(start_timestamp) = search_request.start_timestamp { + quickwit_common::tracing_utils::record_current_span_attribute( + "start_timestamp", + start_timestamp, + ); + } + if let Some(end_timestamp) = search_request.end_timestamp { + quickwit_common::tracing_utils::record_current_span_attribute( + "end_timestamp", + end_timestamp, + ); + } if let Some(max_total_split_searches) = searcher_context.searcher_config.max_splits_per_search && max_total_split_searches < num_splits