Make logging 30% more compact

quickwit-oss · Mar 28, 2024 · 96fd9ca · 96fd9ca
1 parent edbccba
commit 96fd9ca
Show file tree

Hide file tree

Showing 3 changed files with 66 additions and 31 deletions.
diff --git a/distribution/lambda/Makefile b/distribution/lambda/Makefile
@@ -111,7 +111,7 @@ bench-index:
 	done
 
 bench-search-term:
-	export QW_LAMBDA_LOG_SPAN_BOUNDARIES=true
+	export QW_LAMBDA_ENABLE_VERBOSE_JSON_LOGS=true
 	mem_sizes=( 1024 2048 4096 8192 )
 	for mem_size in "$${mem_sizes[@]}"
 	do
@@ -121,7 +121,7 @@ bench-search-term:
 	done
 
 bench-search-histogram:
-	export QW_LAMBDA_LOG_SPAN_BOUNDARIES=true
+	export QW_LAMBDA_ENABLE_VERBOSE_JSON_LOGS=true
 	mem_sizes=( 1024 2048 4096 8192 )
 	for mem_size in "$${mem_sizes[@]}"
 	do
@@ -143,3 +143,7 @@ bench-search:
 
 test-mock-data-endpoints:
 	python -c 'from cdk import cli; cli.test_mock_data_endpoints()'
+
+
+dl-log:
+	python -c 'from cdk import cli; cli.download_logs_to_file("2c880455-b6e4-497e-80b9-b168b3cd0c46", "MockDataStack-QuickwitIndexerLambda3D0AD72D-2PbWB4ocAqpf",1711618460.0016074)'
diff --git a/quickwit/quickwit-lambda/src/environment.rs b/quickwit/quickwit-lambda/src/environment.rs
@@ -24,10 +24,11 @@ use once_cell::sync::Lazy;
 pub static INDEX_ID: Lazy<String> =
     Lazy::new(|| var("QW_LAMBDA_INDEX_ID").expect("QW_LAMBDA_INDEX_ID must be set"));
 
-/// Configure the fmt tracing subscriber to log span boundaries. This is very verbose and is
-/// only used to generate advanced KPIs from Lambda runs (e.g for blogpost benchmarks)
-pub static LOG_SPAN_BOUNDARIES: Lazy<bool> =
-    Lazy::new(|| var("QW_LAMBDA_LOG_SPAN_BOUNDARIES").is_ok_and(|v| v.as_str() == "true"));
+/// Configure the fmt tracing subscriber to log as json and include span
+/// boundaries. This is very verbose and is only used to generate advanced KPIs
+/// from Lambda runs (e.g for blog post benchmarks)
+pub static ENABLE_VERBOSE_JSON_LOGS: Lazy<bool> =
+    Lazy::new(|| var("QW_LAMBDA_ENABLE_VERBOSE_JSON_LOGS").is_ok_and(|v| v.as_str() == "true"));
 
 pub static OPENTELEMETRY_URL: Lazy<Option<String>> =
     Lazy::new(|| var("QW_LAMBDA_OPENTELEMETRY_URL").ok());

diff --git a/quickwit/quickwit-lambda/src/logger.rs b/quickwit/quickwit-lambda/src/logger.rs
@@ -32,46 +32,76 @@ use tracing_subscriber::prelude::*;
 use tracing_subscriber::registry::LookupSpan;
 use tracing_subscriber::{EnvFilter, Layer};
 
-use crate::environment::{LOG_SPAN_BOUNDARIES, OPENTELEMETRY_AUTHORIZATION, OPENTELEMETRY_URL};
+use crate::environment::{
+    ENABLE_VERBOSE_JSON_LOGS, OPENTELEMETRY_AUTHORIZATION, OPENTELEMETRY_URL,
+};
 
 static TRACER_PROVIDER: OnceCell<Option<TracerProvider>> = OnceCell::new();
 pub(crate) const RUNTIME_CONTEXT_SPAN: &str = "runtime_context";
 
-fn fmt_layer<S>(level: Level) -> impl Layer<S>
-where
-    S: for<'a> LookupSpan<'a>,
-    S: tracing::Subscriber,
-{
+fn fmt_env_filter(level: Level) -> EnvFilter {
     let default_filter = format!("quickwit={level}")
         .parse()
         .expect("Invalid default filter");
-    let env_filter = EnvFilter::builder()
+    EnvFilter::builder()
         .with_default_directive(default_filter)
-        .from_env_lossy();
+        .from_env_lossy()
+}
+
+fn fmt_time_format() -> UtcTime<std::vec::Vec<time::format_description::FormatItem<'static>>> {
+    // We do not rely on the Rfc3339 implementation, because it has a nanosecond precision.
+    // See discussion here: https://github.com/time-rs/time/discussions/418
+    UtcTime::new(
+        time::format_description::parse(
+            "[year]-[month]-[day]T[hour]:[minute]:[second].[subsecond digits:3]Z",
+        )
+        .expect("Time format invalid."),
+    )
+}
+
+fn compact_fmt_layer<S>(level: Level) -> impl Layer<S>
+where
+    S: for<'a> LookupSpan<'a>,
+    S: tracing::Subscriber,
+{
     let event_format = tracing_subscriber::fmt::format()
         .with_target(true)
-        .with_timer(
-            // We do not rely on the Rfc3339 implementation, because it has a nanosecond precision.
-            // See discussion here: https://github.com/time-rs/time/discussions/418
-            UtcTime::new(
-                time::format_description::parse(
-                    "[year]-[month]-[day]T[hour]:[minute]:[second].[subsecond digits:3]Z",
-                )
-                .expect("Time format invalid."),
-            ),
-        )
+        .with_timer(fmt_time_format())
+        .compact();
+
+    tracing_subscriber::fmt::layer::<S>()
+        .event_format(event_format)
+        .with_ansi(false)
+        .with_filter(fmt_env_filter(level))
+}
+
+fn json_fmt_layer<S>(level: Level) -> impl Layer<S>
+where
+    S: for<'a> LookupSpan<'a>,
+    S: tracing::Subscriber,
+{
+    let event_format = tracing_subscriber::fmt::format()
+        .with_target(true)
+        .with_timer(fmt_time_format())
         .json();
-    let fmt_span = if *LOG_SPAN_BOUNDARIES {
-        FmtSpan::NEW | FmtSpan::CLOSE
-    } else {
-        FmtSpan::NONE
-    };
     tracing_subscriber::fmt::layer::<S>()
-        .with_span_events(fmt_span)
+        .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
         .event_format(event_format)
         .fmt_fields(JsonFields::default())
         .with_ansi(false)
-        .with_filter(env_filter)
+        .with_filter(fmt_env_filter(level))
+}
+
+fn fmt_layer<S>(level: Level) -> Box<dyn Layer<S> + Send + Sync + 'static>
+where
+    S: for<'a> LookupSpan<'a>,
+    S: tracing::Subscriber,
+{
+    if *ENABLE_VERBOSE_JSON_LOGS {
+        json_fmt_layer(level).boxed()
+    } else {
+        compact_fmt_layer(level).boxed()
+    }
 }
 
 fn otlp_layer<S>(