fix(query): tracing was broken (#18376)

Author: forsaken628

scripts/ci/deploy/databend-query-cluster-tracing.sh

@@ -0,0 +1,51 @@
+#!/bin/bash
+# Copyright 2022 The Databend Authors.
+# SPDX-License-Identifier: Apache-2.0.
+
+set -e
+
+SCRIPT_PATH="$(cd "$(dirname "$0")" >/dev/null 2>&1 && pwd)"
+cd "$SCRIPT_PATH/../../.." || exit
+BUILD_PROFILE=${BUILD_PROFILE:-debug}
+
+killall databend-query || true
+killall databend-meta || true
+sleep 1
+
+for bin in databend-query databend-meta; do
+	if test -n "$(pgrep $bin)"; then
+		echo "The $bin is not killed. force killing."
+		killall -9 $bin || true
+	fi
+done
+
+# Wait for killed process to cleanup resources
+sleep 1
+
+echo 'Start databend-meta...'
+nohup target/${BUILD_PROFILE}/databend-meta -c scripts/ci/deploy/config/databend-meta-node-1.toml &
+echo "Waiting on databend-meta 10 seconds..."
+python3 scripts/ci/wait_tcp.py --timeout 30 --port 9191
+
+export RUST_BACKTRACE=1
+export LOG_TRACING_ON=true
+
+echo 'Start databend-query node-1'
+nohup target/${BUILD_PROFILE}/databend-query -c scripts/ci/deploy/config/databend-query-node-1.toml --internal-enable-sandbox-tenant --log-tracing-level Warn,databend_=Debug,openraft=Info >./.databend/query-1.out 2>&1 &
+
+echo "Waiting on node-1..."
+python3 scripts/ci/wait_tcp.py --timeout 30 --port 9091
+
+echo 'Start databend-query node-2'
+nohup target/${BUILD_PROFILE}/databend-query -c scripts/ci/deploy/config/databend-query-node-2.toml --internal-enable-sandbox-tenant --log-tracing-level Warn,databend_=Debug,openraft=Info >./.databend/query-2.out 2>&1 &
+
+echo "Waiting on node-2..."
+python3 scripts/ci/wait_tcp.py --timeout 30 --port 9092
+
+echo 'Start databend-query node-3'
+nohup target/${BUILD_PROFILE}/databend-query -c scripts/ci/deploy/config/databend-query-node-3.toml --internal-enable-sandbox-tenant --log-tracing-level Warn,databend_=Debug,openraft=Info >./.databend/query-3.out 2>&1 &
+
+echo "Waiting on node-3..."
+python3 scripts/ci/wait_tcp.py --timeout 30 --port 9093
+
+echo "All done..."

src/query/expression/src/block.rs

@@ -146,12 +146,12 @@ impl BlockEntry {
     /// Calling this method with an out-of-bounds index is *[undefined behavior]*
     pub unsafe fn index_unchecked(&self, index: usize) -> ScalarRef {
         match self {
-            BlockEntry::Const(scalar, _, n) => {
+            BlockEntry::Const(scalar, _, _n) => {
                 #[cfg(debug_assertions)]
-                if index >= *n {
+                if index >= *_n {
                     panic!(
                         "index out of bounds: the len is {:?} but the index is {}",
-                        n, index
+                        _n, index
                     )
                 }
 

src/query/service/src/interpreters/interpreter_select.rs

@@ -108,7 +108,7 @@ impl SelectInterpreter {
         DataSchemaRefExt::create(fields)
     }
 
-    #[inline]
+    #[fastrace::trace(name = "SelectInterpreter::build_physical_plan")]
     #[async_backtrace::framed]
     pub async fn build_physical_plan(&self) -> Result<PhysicalPlan> {
         let mut builder = PhysicalPlanBuilder::new(self.metadata.clone(), self.ctx.clone(), false);
@@ -119,6 +119,7 @@ impl SelectInterpreter {
             .await
     }
 
+    #[fastrace::trace(name = "SelectInterpreter::build_pipeline")]
     #[async_backtrace::framed]
     pub async fn build_pipeline(
         &self,
@@ -275,7 +276,7 @@ impl Interpreter for SelectInterpreter {
 
     /// This method will create a new pipeline
     /// The QueryPipelineBuilder will use the optimized plan to generate a Pipeline
-    #[fastrace::trace]
+    #[fastrace::trace(name = "SelectInterpreter::execute2")]
     #[async_backtrace::framed]
     async fn execute2(&self) -> Result<PipelineBuildResult> {
         self.attach_tables_to_ctx();

src/query/service/src/servers/http/v1/http_query_handlers.rs

@@ -432,6 +432,7 @@ async fn query_page_handler(
 
 #[poem::handler]
 #[async_backtrace::framed]
+#[fastrace::trace]
 pub(crate) async fn query_handler(
     ctx: &HttpQueryContext,
     Json(mut req): Json<HttpQueryRequest>,

src/query/service/src/servers/http/v1/query/execute_state.rs

@@ -279,8 +279,8 @@ impl Executor {
         let state = match &guard.state {
             Starting(s) => {
                 info!(
-                    "[HTTP-QUERY] Query {} state transitioning from Starting to Stopped, reason: {:?}",
-                    &guard.query_id, reason
+                    query_id = guard.query_id, reason:? = reason;
+                    "[HTTP-QUERY] Query state transitioning from Starting to Stopped"
                 );
                 if let Err(e) = &reason {
                     InterpreterQueryLog::log_finish(
@@ -347,6 +347,7 @@ impl Executor {
 
 impl ExecuteState {
     #[async_backtrace::framed]
+    #[fastrace::trace(name = "ExecuteState::try_start_query")]
     pub(crate) async fn try_start_query(
         executor: Arc<Mutex<Executor>>,
         sql: String,

src/query/service/src/servers/http/v1/query/http_query.rs

@@ -38,6 +38,7 @@ use databend_common_metrics::http::metrics_incr_http_response_errors_count;
 use databend_common_settings::ScopeLevel;
 use databend_storages_common_session::TempTblMgrRef;
 use databend_storages_common_session::TxnState;
+use fastrace::future::FutureExt;
 use http::StatusCode;
 use log::error;
 use log::info;
@@ -441,7 +442,7 @@ fn try_set_txn(
 
 impl HttpQuery {
     #[async_backtrace::framed]
-    #[fastrace::trace]
+    #[fastrace::trace(name = "HttpQuery::try_create")]
     pub async fn try_create(
         http_ctx: &HttpQueryContext,
         req: HttpQueryRequest,
@@ -790,6 +791,7 @@ impl HttpQuery {
     }
 
     pub async fn start_query(&mut self, sql: String) -> Result<()> {
+        let span = fastrace::Span::enter_with_local_parent("HttpQuery::start_query");
         let (block_sender, query_context) = {
             let state = self.executor.lock();
             let ExecuteState::Starting(state) = &state.state else {
@@ -847,7 +849,8 @@ impl HttpQuery {
                     Executor::start_to_stop(&query_state, ExecuteState::Stopped(Box::new(state)));
                     block_sender.close();
                 }
-            },
+            }
+            .in_span(span),
             None,
         )?;
 

src/query/service/src/spillers/spiller.rs

@@ -162,6 +162,7 @@ impl Spiller {
     }
 
     /// Spill some [`DataBlock`] to storage. These blocks will be concat into one.
+    #[fastrace::trace(name = "Spiller::spill")]
     pub async fn spill(&self, data_block: Vec<DataBlock>) -> Result<Location> {
         let (location, layout, data_size) = self.spill_unmanage(data_block).await?;
 
@@ -325,6 +326,7 @@ impl Spiller {
 
     /// Read a certain file to a [`DataBlock`].
     /// We should guarantee that the file is managed by this spiller.
+    #[fastrace::trace(name = "Spiller::read_spilled_file")]
     pub async fn read_spilled_file(&self, location: &Location) -> Result<DataBlock> {
         let layout = self.ctx.get_spill_layout(location).unwrap();
         self.read_unmanage_spilled_file(location, &layout).await