search: add query_ast, counts, and warmup byte span attributes

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<opentelemetry::Value>) {
+    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`.

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);

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