feat(query): add config for query profile log (databendlabs#13987)

src/binaries/metabench/main.rs

@@ -45,10 +45,7 @@ use common_meta_types::Operation;
 use common_meta_types::TxnRequest;
 use common_tracing::init_logging;
 use common_tracing::FileConfig;
-use common_tracing::OTLPConfig;
-use common_tracing::QueryLogConfig;
 use common_tracing::StderrConfig;
-use common_tracing::TracingConfig;
 use databend_meta::version::METASRV_COMMIT_VERSION;
 use serde::Deserialize;
 use serde::Serialize;
@@ -98,9 +95,7 @@ async fn main() {
             level: "WARN".to_string(),
             format: "text".to_string(),
         },
-        otlp: OTLPConfig::default(),
-        query: QueryLogConfig::default(),
-        tracing: TracingConfig::default(),
+        ..Default::default()
     };
 
     let _guards = init_logging("databend-metabench", &log_config, BTreeMap::new());

src/binaries/metactl/main.rs

@@ -15,9 +15,6 @@
 #![allow(clippy::uninlined_format_args)]
 
 mod grpc;
-use common_tracing::OTLPConfig;
-use common_tracing::QueryLogConfig;
-use common_tracing::TracingConfig;
 use grpc::export_meta;
 
 mod snapshot;
@@ -33,7 +30,6 @@ use common_meta_raft_store::config::RaftConfig;
 use common_tracing::init_logging;
 use common_tracing::Config as LogConfig;
 use common_tracing::FileConfig;
-use common_tracing::StderrConfig;
 use databend_meta::version::METASRV_COMMIT_VERSION;
 use serde::Deserialize;
 use serde::Serialize;
@@ -123,10 +119,7 @@ async fn main() -> anyhow::Result<()> {
             dir: ".databend/logs".to_string(),
             format: "text".to_string(),
         },
-        stderr: StderrConfig::default(),
-        otlp: OTLPConfig::default(),
-        query: QueryLogConfig::default(),
-        tracing: TracingConfig::default(),
+        ..Default::default()
     };
 
     let _guards = init_logging("metactl", &log_config, BTreeMap::new());

src/common/tracing/src/config.rs

@@ -23,6 +23,7 @@ pub struct Config {
     pub stderr: StderrConfig,
     pub otlp: OTLPConfig,
     pub query: QueryLogConfig,
+    pub profile: ProfileLogConfig,
     pub tracing: TracingConfig,
 }
 
@@ -41,23 +42,7 @@ impl Config {
                 level: "WARN".to_string(),
                 format: "text".to_string(),
             },
-            otlp: OTLPConfig {
-                on: false,
-                level: "INFO".to_string(),
-                endpoint: "http://127.0.0.1:4317".to_string(),
-                labels: BTreeMap::new(),
-            },
-            query: QueryLogConfig {
-                on: false,
-                dir: "".to_string(),
-                otlp_endpoint: "".to_string(),
-                labels: BTreeMap::new(),
-            },
-            tracing: TracingConfig {
-                on: false,
-                capture_log_level: "TRACE".to_string(),
-                otlp_endpoint: "http://127.0.0.1:4317".to_string(),
-            },
+            ..Default::default()
         }
     }
 }
@@ -195,6 +180,41 @@ impl Default for QueryLogConfig {
     }
 }
 
+#[derive(Clone, Debug, PartialEq, Eq, serde::Serialize)]
+pub struct ProfileLogConfig {
+    pub on: bool,
+    pub dir: String,
+    pub otlp_endpoint: String,
+    pub labels: BTreeMap<String, String>,
+}
+
+impl Display for ProfileLogConfig {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        let labels = self
+            .labels
+            .iter()
+            .map(|(k, v)| format!("{}:{}", k, v))
+            .collect::<Vec<_>>()
+            .join(",");
+        write!(
+            f,
+            "enabled={}, dir={}, otlp_endpoint={}, labels={}",
+            self.on, self.dir, self.otlp_endpoint, labels,
+        )
+    }
+}
+
+impl Default for ProfileLogConfig {
+    fn default() -> Self {
+        Self {
+            on: false,
+            dir: "".to_string(),
+            otlp_endpoint: "".to_string(),
+            labels: BTreeMap::new(),
+        }
+    }
+}
+
 #[derive(Clone, Debug, PartialEq, Eq, serde::Serialize)]
 pub struct TracingConfig {
     pub on: bool,

src/common/tracing/src/init.rs

@@ -136,6 +136,7 @@ pub fn init_logging(
     // Initialize logging
     let mut normal_logger = fern::Dispatch::new();
     let mut query_logger = fern::Dispatch::new();
+    let mut profile_logger = fern::Dispatch::new();
 
     // File logger
     if cfg.file.on {
@@ -201,26 +202,50 @@ pub fn init_logging(
         }
     }
 
+    // Profile logger
+    if cfg.profile.on {
+        if !cfg.profile.dir.is_empty() {
+            let (profile_log_file, flush_guard) = new_file_log_writer(&cfg.profile.dir, name);
+            guards.push(Box::new(flush_guard));
+            profile_logger =
+                profile_logger.chain(Box::new(profile_log_file) as Box<dyn Write + Send>);
+        }
+        if !cfg.profile.otlp_endpoint.is_empty() {
+            let mut labels = labels.clone();
+            labels.insert("category".to_string(), "profile".to_string());
+            labels.extend(cfg.profile.labels.clone());
+            let logger = new_otlp_log_writer(&cfg.profile.otlp_endpoint, labels);
+            profile_logger = profile_logger.chain(Box::new(logger) as Box<dyn Log>);
+        }
+    }
+
     let logger = fern::Dispatch::new()
         .chain(
             fern::Dispatch::new()
-                .level_for("query", LevelFilter::Off)
+                .level_for("databend::log::query", LevelFilter::Off)
+                .level_for("databend::log::profile", LevelFilter::Off)
                 .filter(|meta| {
                     if meta.target().starts_with("databend_")
                         || meta.target().starts_with("common_")
                     {
                         true
                     } else {
-                        meta.level() >= LevelFilter::Error
+                        meta.level() <= LevelFilter::Error
                     }
                 })
                 .chain(normal_logger),
         )
         .chain(
             fern::Dispatch::new()
                 .level(LevelFilter::Off)
-                .level_for("query", LevelFilter::Info)
+                .level_for("databend::log::query", LevelFilter::Info)
                 .chain(query_logger),
+        )
+        .chain(
+            fern::Dispatch::new()
+                .level(LevelFilter::Off)
+                .level_for("databend::log::profile", LevelFilter::Info)
+                .chain(profile_logger),
         );
 
     // Set global logger

src/common/tracing/src/lib.rs

@@ -23,6 +23,7 @@ mod panic_hook;
 pub use crate::config::Config;
 pub use crate::config::FileConfig;
 pub use crate::config::OTLPConfig;
+pub use crate::config::ProfileLogConfig;
 pub use crate::config::QueryLogConfig;
 pub use crate::config::StderrConfig;
 pub use crate::config::TracingConfig;

src/meta/service/src/configs/outer_v0.rs

@@ -23,6 +23,7 @@ use common_meta_types::MetaStartupError;
 use common_tracing::Config as InnerLogConfig;
 use common_tracing::FileConfig as InnerFileLogConfig;
 use common_tracing::OTLPConfig;
+use common_tracing::ProfileLogConfig;
 use common_tracing::QueryLogConfig;
 use common_tracing::StderrConfig as InnerStderrLogConfig;
 use common_tracing::TracingConfig;
@@ -592,6 +593,7 @@ impl Into<InnerLogConfig> for LogConfig {
             stderr: self.stderr.into(),
             otlp: OTLPConfig::default(),
             query: QueryLogConfig::default(),
+            profile: ProfileLogConfig::default(),
             tracing: TracingConfig::default(),
         }
     }

src/query/config/src/config.rs

@@ -46,6 +46,7 @@ use common_storage::StorageConfig as InnerStorageConfig;
 use common_tracing::Config as InnerLogConfig;
 use common_tracing::FileConfig as InnerFileLogConfig;
 use common_tracing::OTLPConfig as InnerOTLPLogConfig;
+use common_tracing::ProfileLogConfig as InnerProfileLogConfig;
 use common_tracing::QueryLogConfig as InnerQueryLogConfig;
 use common_tracing::StderrConfig as InnerStderrLogConfig;
 use common_tracing::TracingConfig as InnerTracingConfig;
@@ -1800,6 +1801,9 @@ pub struct LogConfig {
     #[clap(flatten)]
     pub query: QueryLogConfig,
 
+    #[clap(flatten)]
+    pub profile: ProfileLogConfig,
+
     #[clap(flatten)]
     pub tracing: TracingConfig,
 }
@@ -1861,13 +1865,25 @@ impl TryInto<InnerLogConfig> for LogConfig {
             }
         }
 
+        let mut profile: InnerProfileLogConfig = self.profile.try_into()?;
+        if profile.on && profile.dir.is_empty() && profile.otlp_endpoint.is_empty() {
+            if file.dir.is_empty() {
+                return Err(ErrorCode::InvalidConfig(
+                    "`dir` or `file.dir` must be set when `profile.dir` is empty".to_string(),
+                ));
+            } else {
+                profile.dir = format!("{}/profiles", &file.dir);
+            }
+        }
+
         let tracing: InnerTracingConfig = self.tracing.try_into()?;
 
         Ok(InnerLogConfig {
             file,
             stderr: self.stderr.try_into()?,
             otlp,
             query,
+            profile,
             tracing,
         })
     }
@@ -1882,6 +1898,7 @@ impl From<InnerLogConfig> for LogConfig {
             stderr: inner.stderr.into(),
             otlp: inner.otlp.into(),
             query: inner.query.into(),
+            profile: inner.profile.into(),
             tracing: inner.tracing.into(),
 
             // Deprecated fields
@@ -2117,6 +2134,63 @@ impl From<InnerQueryLogConfig> for QueryLogConfig {
     }
 }
 
+#[derive(Clone, Debug, PartialEq, Eq, Serialize, Deserialize, Args)]
+#[serde(default)]
+pub struct ProfileLogConfig {
+    #[clap(long = "log-profile-on", value_name = "VALUE", default_value = "false", action = ArgAction::Set, num_args = 0..=1, require_equals = true, default_missing_value = "true")]
+    #[serde(rename = "on")]
+    pub log_profile_on: bool,
+
+    /// Profile Log file dir
+    #[clap(long = "log-profile-dir", value_name = "VALUE", default_value = "")]
+    #[serde(rename = "dir")]
+    pub log_profile_dir: String,
+
+    /// Profile Log OpenTelemetry OTLP endpoint
+    #[clap(
+        long = "log-profile-otlp-endpoint",
+        value_name = "VALUE",
+        default_value = ""
+    )]
+    #[serde(rename = "otlp_endpoint")]
+    pub log_profile_otlp_endpoint: String,
+
+    /// Profile Log Labels
+    #[clap(skip)]
+    #[serde(rename = "labels")]
+    pub log_profile_otlp_labels: BTreeMap<String, String>,
+}
+
+impl Default for ProfileLogConfig {
+    fn default() -> Self {
+        InnerProfileLogConfig::default().into()
+    }
+}
+
+impl TryInto<InnerProfileLogConfig> for ProfileLogConfig {
+    type Error = ErrorCode;
+
+    fn try_into(self) -> Result<InnerProfileLogConfig> {
+        Ok(InnerProfileLogConfig {
+            on: self.log_profile_on,
+            dir: self.log_profile_dir,
+            otlp_endpoint: self.log_profile_otlp_endpoint,
+            labels: self.log_profile_otlp_labels,
+        })
+    }
+}
+
+impl From<InnerProfileLogConfig> for ProfileLogConfig {
+    fn from(inner: InnerProfileLogConfig) -> Self {
+        Self {
+            log_profile_on: inner.on,
+            log_profile_dir: inner.dir,
+            log_profile_otlp_endpoint: inner.otlp_endpoint,
+            log_profile_otlp_labels: inner.labels,
+        }
+    }
+}
+
 #[derive(Clone, Debug, PartialEq, Eq, Serialize, Deserialize, Args)]
 #[serde(default)]
 pub struct TracingConfig {

src/query/service/src/interpreters/common/query_log.rs

@@ -59,7 +59,7 @@ impl InterpreterQueryLog {
     fn write_log(event: QueryLogElement) -> Result<()> {
         let event_str = serde_json::to_string(&event)?;
         // log the query log in JSON format
-        info!(target: "query", "{}", event_str);
+        info!(target: "databend::log::query", "{}", event_str);
         // log the query event in the system log
         info!("query: {} becomes {:?}", event.query_id, event.log_type);
         QueryLogQueue::instance()?.append_data(event)

src/query/service/src/interpreters/interpreter.rs

@@ -93,7 +93,7 @@ pub trait Interpreter: Sync + Send {
                         profiles: Vec<PlanProfile>,
                     }
 
-                    info!(target: "query_profiles", "{}", serde_json::to_string(&QueryProfiles {
+                    info!(target: "databend::log::profile", "{}", serde_json::to_string(&QueryProfiles {
                         query_id: query_ctx.get_id(),
                         profiles: query_profiles,
                     })?);

src/query/service/tests/it/storages/testdata/configs_table_basic.txt

@@ -31,14 +31,17 @@ DB.Table: 'system'.'configs', Table: configs-table_id:1, ver:0, Engine: SystemCo
 | 'log'     | 'otlp.endpoint'                            | 'http://127.0.0.1:4317'                                        | ''       |
 | 'log'     | 'otlp.level'                               | 'INFO'                                                         | ''       |
 | 'log'     | 'otlp.on'                                  | 'false'                                                        | ''       |
+| 'log'     | 'profile.dir'                              | ''                                                             | ''       |
+| 'log'     | 'profile.on'                               | 'false'                                                        | ''       |
+| 'log'     | 'profile.otlp_endpoint'                    | ''                                                             | ''       |
 | 'log'     | 'query.dir'                                | ''                                                             | ''       |
 | 'log'     | 'query.on'                                 | 'false'                                                        | ''       |
 | 'log'     | 'query.otlp_endpoint'                      | ''                                                             | ''       |
 | 'log'     | 'query_enabled'                            | 'null'                                                         | ''       |
 | 'log'     | 'stderr.format'                            | 'text'                                                         | ''       |
 | 'log'     | 'stderr.level'                             | 'WARN'                                                         | ''       |
 | 'log'     | 'stderr.on'                                | 'true'                                                         | ''       |
-| 'log'     | 'tracing.capture_log_level'                | 'TRACE'                                                        | ''       |
+| 'log'     | 'tracing.capture_log_level'                | 'INFO'                                                         | ''       |
 | 'log'     | 'tracing.on'                               | 'false'                                                        | ''       |
 | 'log'     | 'tracing.otlp_endpoint'                    | 'http://127.0.0.1:4317'                                        | ''       |
 | 'meta'    | 'auto_sync_interval'                       | '0'                                                            | ''       |