chore: clean up log statements in query_executor (#25102)

* chore: clean up log statements in query_executor

There were several tracing statements that were making the log output
for each query rather verbose. This reduces the amount of info!
statements by converting them to debug!, and clarifies some of the logged
messages.

The type of query is also logged, i.e, "sql" vs. "influxql", which was
not being done before.

* refactor: switch back important log to info
pull/25108/head
Trevor Hilton 2024-06-26 11:51:12 -04:00 committed by GitHub
parent 2ddef9f8da
commit 7cfaa6aeaf
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 89 additions and 94 deletions

134
Cargo.lock generated
View File

@ -559,7 +559,7 @@ checksum = "16e62a023e7c117e27523144c5d2459f4397fcc3cab0085af8e2224f643a0193"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -570,7 +570,7 @@ checksum = "c6fa2087f2753a7da8cc1c0dbfcf89579dd57458e36769de5ac750b4671737ca"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -719,9 +719,9 @@ checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a"
[[package]]
name = "bitflags"
version = "2.5.0"
version = "2.6.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cf4b9d6a944f767f8e5e0db018570623c85f3d925ac718db4e06d0187adb21c1"
checksum = "b048fb63fd8b5923fc5aa7b340d8e156aec7ec02f0c78fa8a6ddc2613f6f71de"
dependencies = [
"serde",
]
@ -850,9 +850,9 @@ dependencies = [
[[package]]
name = "cc"
version = "1.0.99"
version = "1.0.101"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "96c51067fd44124faa7f870b4b1c969379ad32b2ba805aa959430ceaa384f695"
checksum = "ac367972e516d45567c7eafc73d24e1c193dcf200a8d94e9db7b3d38b349572d"
dependencies = [
"jobserver",
"libc",
@ -993,7 +993,7 @@ dependencies = [
"heck 0.5.0",
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -1174,9 +1174,9 @@ dependencies = [
[[package]]
name = "croaring-sys"
version = "2.0.0"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ab5260027c04c33d67f405589d9c26e1e991fe062fb165f3094c9836e6c3b17f"
checksum = "3e5fed89265a702f0085844237a7ebbadf8a7c42de6304fddca30a5013f9aecb"
dependencies = [
"cc",
]
@ -1285,7 +1285,7 @@ checksum = "f46882e17999c6cc590af592290432be3bce0428cb0d5f8b6715e4dc7b383eb3"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -1309,7 +1309,7 @@ dependencies = [
"proc-macro2",
"quote",
"strsim",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -1320,7 +1320,7 @@ checksum = "733cabb43482b1a1b53eee8583c2b9e8684d592215ea83efd305dd31bc2f0178"
dependencies = [
"darling_core",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -1808,9 +1808,9 @@ dependencies = [
[[package]]
name = "either"
version = "1.12.0"
version = "1.13.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "3dca9240753cf90908d7e4aac30f630662b02aebaa1b58a3cadabdb23385b58b"
checksum = "60b1af1c220855b6ceac025d3f6ecdd2b7c4894bfe9cd9bda4fbb4bc7c0d4cf0"
dependencies = [
"serde",
]
@ -1956,7 +1956,7 @@ checksum = "55ac459de2512911e4b674ce33cf20befaba382d05b62b008afc1c8b57cbf181"
dependencies = [
"futures-core",
"futures-sink",
"spin 0.9.8",
"spin",
]
[[package]]
@ -2041,7 +2041,7 @@ checksum = "87750cf4b7a4c0625b1529e4c543c2182106e4dedc60a2a6455e00d212c489ac"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -3122,11 +3122,11 @@ dependencies = [
[[package]]
name = "lazy_static"
version = "1.4.0"
version = "1.5.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e2abad23fbc42b3700f2f279844dc832adb2b2eb069b2df918f455c4e18cc646"
checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe"
dependencies = [
"spin 0.5.2",
"spin",
]
[[package]]
@ -3459,7 +3459,7 @@ version = "0.29.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "71e2746dc3a24dd78b3cfcb7be93368c6de9963d30f43a6a73998a9cf4b17b46"
dependencies = [
"bitflags 2.5.0",
"bitflags 2.6.0",
"cfg-if",
"cfg_aliases",
"libc",
@ -3933,7 +3933,7 @@ checksum = "2f38a4412a78282e09a2cf38d195ea5420d15ba0602cb375210efbc877243965"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -4052,14 +4052,14 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "5f12335488a2f3b0a83b14edad48dca9879ce89b2edd10e80237e4e852dd645e"
dependencies = [
"proc-macro2",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
name = "proc-macro2"
version = "1.0.85"
version = "1.0.86"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "22244ce15aa966053a896d1accb3a6e68469b97c7f33f284b99f0d576879fc23"
checksum = "5e719e8df665df0d1c8fbfd238015744736151d4445ec0836b8e628aae103b77"
dependencies = [
"unicode-ident",
]
@ -4092,13 +4092,13 @@ dependencies = [
[[package]]
name = "proptest"
version = "1.4.0"
version = "1.5.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "31b476131c3c86cb68032fdc5cb6d5a1045e3e42d96b69fa599fd77701e1f5bf"
checksum = "b4c2511913b88df1637da85cc8d96ec8e43a3f8bb8ccb71ee1ac240d6f3df58d"
dependencies = [
"bit-set",
"bit-vec",
"bitflags 2.5.0",
"bitflags 2.6.0",
"lazy_static",
"num-traits",
"rand",
@ -4147,7 +4147,7 @@ dependencies = [
"prost 0.12.6",
"prost-types 0.12.6",
"regex",
"syn 2.0.66",
"syn 2.0.68",
"tempfile",
]
@ -4174,7 +4174,7 @@ dependencies = [
"itertools 0.12.1",
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -4357,7 +4357,7 @@ version = "0.5.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c82cf8cff14456045f55ec4241383baeff27af886adb72ffb2162f99911de0fd"
dependencies = [
"bitflags 2.5.0",
"bitflags 2.6.0",
]
[[package]]
@ -4504,7 +4504,7 @@ dependencies = [
"cfg-if",
"getrandom",
"libc",
"spin 0.9.8",
"spin",
"untrusted",
"windows-sys 0.52.0",
]
@ -4556,7 +4556,7 @@ version = "0.38.34"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "70dc5ec042f7a43c4a73241207cecc9873a06d45debb38b329f8541d85c2730f"
dependencies = [
"bitflags 2.5.0",
"bitflags 2.6.0",
"errno",
"libc",
"linux-raw-sys",
@ -4761,7 +4761,7 @@ version = "2.11.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c627723fd09706bacdb5cf41499e95098555af3c3c29d014dc3c458ef6be11c0"
dependencies = [
"bitflags 2.5.0",
"bitflags 2.6.0",
"core-foundation",
"core-foundation-sys",
"libc",
@ -4807,14 +4807,14 @@ checksum = "500cbc0ebeb6f46627f50f3f5811ccf6bf00643be300b4c3eabc0ef55dc5b5ba"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
name = "serde_json"
version = "1.0.117"
version = "1.0.118"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "455182ea6142b14f93f4bc5320a2b31c1f266b66a4a5c858b013302a5d8cbfc3"
checksum = "d947f6b3163d8857ea16c4fa0dd4840d52f3041039a85decd46867eb1abef2e4"
dependencies = [
"itoa",
"ryu",
@ -4860,7 +4860,7 @@ dependencies = [
"darling",
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5041,7 +5041,7 @@ dependencies = [
"heck 0.5.0",
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5060,12 +5060,6 @@ dependencies = [
"windows-sys 0.52.0",
]
[[package]]
name = "spin"
version = "0.5.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "6e63cff320ae2c57904679ba7cb63280a3dc4613885beafb148ee7bf9aa9042d"
[[package]]
name = "spin"
version = "0.9.8"
@ -5113,7 +5107,7 @@ checksum = "01b2e185515564f15375f593fb966b5718bc624ba77fe49fa4616ad619690554"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5230,7 +5224,7 @@ checksum = "1ed31390216d20e538e447a7a9b959e06ed9fc51c37b514b46eb758016ecd418"
dependencies = [
"atoi",
"base64 0.21.7",
"bitflags 2.5.0",
"bitflags 2.6.0",
"byteorder",
"bytes",
"crc",
@ -5273,7 +5267,7 @@ checksum = "7c824eb80b894f926f89a0b9da0c7f435d27cdd35b8c655b114e58223918577e"
dependencies = [
"atoi",
"base64 0.21.7",
"bitflags 2.5.0",
"bitflags 2.6.0",
"byteorder",
"crc",
"dotenvy",
@ -5353,9 +5347,9 @@ checksum = "7da8b5736845d9f2fcb837ea5d9e2628564b3b043a70948a3f0b778838c5fb4f"
[[package]]
name = "strum"
version = "0.26.2"
version = "0.26.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "5d8cec3501a5194c432b2b7976db6b7d10ec95c253208b45f83f7136aa985e29"
checksum = "8fec0f0aef304996cf250b31b5a10dee7980c85da9d759361292b8bca5a18f06"
dependencies = [
"strum_macros",
]
@ -5370,14 +5364,14 @@ dependencies = [
"proc-macro2",
"quote",
"rustversion",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
name = "subtle"
version = "2.6.0"
version = "2.6.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "0d0208408ba0c3df17ed26eb06992cb1a1268d41b2c0e12e65203fbe3972cee5"
checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292"
[[package]]
name = "syn"
@ -5392,9 +5386,9 @@ dependencies = [
[[package]]
name = "syn"
version = "2.0.66"
version = "2.0.68"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c42f3f41a2de00b01c0aaad383c5a45241efc8b2d1eda5661812fda5f3cdcff5"
checksum = "901fa70d88b9d6c98022e23b4136f9f3e54e4662c3bc1bd1d84a42a9a0f0c1e9"
dependencies = [
"proc-macro2",
"quote",
@ -5551,7 +5545,7 @@ checksum = "46c3384250002a6d5af4d114f2845d37b57521033f30d5c3f46c4d70e1197533"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5659,9 +5653,9 @@ dependencies = [
[[package]]
name = "tinyvec"
version = "1.6.0"
version = "1.6.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "87cc5ceb3875bb20c2890005a4e226a4651264a5c75edb2421b52861a0a0cb50"
checksum = "c55115c6fbe2d2bef26eb09ad74bde02d8255476fc0c7b515ef09fbb35742d82"
dependencies = [
"tinyvec_macros",
]
@ -5710,7 +5704,7 @@ checksum = "5f5ae998a069d4b5aba8ee9dad856af7d520c3699e6159b185c2acd48155d39a"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5861,7 +5855,7 @@ dependencies = [
"proc-macro2",
"prost-build",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -5916,7 +5910,7 @@ version = "0.4.4"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "61c5bb1d698276a2443e5ecfabc1008bf15a36c12e6a7176e7bf089ea9131140"
dependencies = [
"bitflags 2.5.0",
"bitflags 2.6.0",
"bytes",
"futures-core",
"futures-util",
@ -6026,7 +6020,7 @@ checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -6235,9 +6229,9 @@ checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821"
[[package]]
name = "uuid"
version = "1.8.0"
version = "1.9.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a183cf7feeba97b4dd1c0d46788634f6221d87fa961b305bed08c851829efcc0"
checksum = "5de17fd2f7da591098415cff336e12965a28061ddace43b59cb3c430179c9439"
dependencies = [
"getrandom",
"serde",
@ -6342,7 +6336,7 @@ dependencies = [
"once_cell",
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
"wasm-bindgen-shared",
]
@ -6376,7 +6370,7 @@ checksum = "e94f17b526d0a461a191c78ea52bbce64071ed5c04c9ffe424dcb38f74171bb7"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
"wasm-bindgen-backend",
"wasm-bindgen-shared",
]
@ -6647,7 +6641,7 @@ dependencies = [
"base64 0.22.1",
"bit-set",
"bit-vec",
"bitflags 2.5.0",
"bitflags 2.6.0",
"byteorder",
"bytes",
"cc",
@ -6714,7 +6708,7 @@ dependencies = [
"similar",
"smallvec",
"socket2",
"spin 0.9.8",
"spin",
"sqlparser",
"sqlx",
"sqlx-core",
@ -6725,7 +6719,7 @@ dependencies = [
"strum",
"subtle",
"syn 1.0.109",
"syn 2.0.66",
"syn 2.0.68",
"thrift",
"tokio",
"tokio-stream",
@ -6777,7 +6771,7 @@ checksum = "15e934569e47891f7d9411f1a451d947a60e000ab3bd24fbb970f000387d1b3b"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]
@ -6797,7 +6791,7 @@ checksum = "ce36e65b0d2999d2aafac989fb249189a141aee1f53c612c1f37d72631959f69"
dependencies = [
"proc-macro2",
"quote",
"syn 2.0.66",
"syn 2.0.68",
]
[[package]]

View File

@ -39,7 +39,7 @@ use iox_query_influxql::frontend::planner::InfluxQLQueryPlanner;
use iox_query_params::StatementParams;
use iox_system_tables::{IoxSystemTable, SystemTableProvider};
use metric::Registry;
use observability_deps::tracing::{debug, info, trace};
use observability_deps::tracing::{debug, info};
use schema::Schema;
use std::any::Any;
use std::collections::HashMap;
@ -100,13 +100,13 @@ impl<W: WriteBuffer> QueryExecutor for QueryExecutorImpl<W> {
async fn query(
&self,
database: &str,
q: &str,
query: &str,
params: Option<StatementParams>,
kind: QueryKind,
span_ctx: Option<SpanContext>,
external_span_ctx: Option<RequestLogContext>,
) -> Result<SendableRecordBatchStream, Self::Error> {
info!("query in executor {}", database);
info!(%database, %query, ?params, ?kind, "QueryExecutorImpl as QueryExecutor::query");
let db = self
.namespace(database, span_ctx.child_span("get database"), false)
.await
@ -121,26 +121,25 @@ impl<W: WriteBuffer> QueryExecutor for QueryExecutorImpl<W> {
let ctx = db.new_query_context(span_ctx, Default::default());
let params = params.unwrap_or_default();
let token = db.record_query(
external_span_ctx.as_ref().map(RequestLogContext::ctx),
"sql",
Box::new(q.to_string()),
params.clone(),
);
info!("plan");
let plan = match kind {
debug!("create query plan");
let (plan, query_type) = match kind {
QueryKind::Sql => {
let planner = SqlQueryPlanner::new();
planner.query(q, params, &ctx).await
(planner.query(query, params.clone(), &ctx).await, "sql")
}
QueryKind::InfluxQl => {
let planner = InfluxQLQueryPlanner::new();
planner.query(q, params, &ctx).await
(planner.query(query, params.clone(), &ctx).await, "influxql")
}
}
.map_err(Error::QueryPlanning);
let plan = match plan {
};
let token = db.record_query(
external_span_ctx.as_ref().map(RequestLogContext::ctx),
query_type,
Box::new(query.to_string()),
params,
);
let plan = match plan.map_err(Error::QueryPlanning) {
Ok(plan) => plan,
Err(e) => {
token.fail();
@ -152,7 +151,7 @@ impl<W: WriteBuffer> QueryExecutor for QueryExecutorImpl<W> {
// TODO: Enforce concurrency limit here
let token = token.permit();
info!("execute_stream");
debug!("execute stream of query results");
match ctx.execute_stream(Arc::clone(&plan)).await {
Ok(query_results) => {
token.success();
@ -396,10 +395,10 @@ impl<B: WriteBuffer> QueryNamespace for Database<B> {
ctx: IOxSessionContext,
) -> Result<Vec<Arc<dyn QueryChunk>>, DataFusionError> {
let _span_recorder = SpanRecorder::new(ctx.child_span("QueryDatabase::chunks"));
debug!(%table_name, ?filters, "Finding chunks for table");
debug!(%table_name, ?filters, "Database as QueryNamespace::chunks");
let Some(table) = self.query_table(table_name).await else {
trace!(%table_name, "No entry for table");
debug!(%table_name, "No entry for table");
return Ok(vec![]);
};
@ -454,12 +453,12 @@ impl<B: WriteBuffer> CatalogProvider for Database<B> {
}
fn schema_names(&self) -> Vec<String> {
info!("CatalogProvider schema_names");
debug!("Database as CatalogProvider::schema_names");
vec![DEFAULT_SCHEMA.to_string(), SYSTEM_SCHEMA.to_string()]
}
fn schema(&self, name: &str) -> Option<Arc<dyn SchemaProvider>> {
info!("CatalogProvider schema {}", name);
debug!(schema_name = %name, "Database as CatalogProvider::schema");
match name {
DEFAULT_SCHEMA => Some(Arc::new(Self::from_namespace(self))),
SYSTEM_SCHEMA => Some(Arc::clone(&self.system_schema_provider) as _),
@ -542,9 +541,11 @@ impl<B: WriteBuffer> TableProvider for QueryTable<B> {
limit: Option<usize>,
) -> datafusion::common::Result<Arc<dyn ExecutionPlan>> {
let filters = filters.to_vec();
info!(
"TableProvider scan {:?} {:?} {:?}",
projection, filters, limit
debug!(
?projection,
?filters,
?limit,
"QueryTable as TableProvider::scan"
);
let mut builder = ProviderBuilder::new(Arc::clone(&self.name), self.schema.clone());