From d81fcdf8ef3f2857db1a51b83a012638a7ecf0fb Mon Sep 17 00:00:00 2001 From: Zanie Blue Date: Thu, 4 Jun 2026 10:12:08 -0500 Subject: [PATCH] Reduce SQLite contention from OpenTelemetry SDK debug logs (#26396) ## Summary - skip `opentelemetry_sdk` DEBUG and TRACE events before formatting or queueing them for the SQLite log sink - preserve INFO, WARN, and ERROR events from the SDK, along with TRACE events from application targets - add a persistence-level regression test for the target and level policy ## Why OpenTelemetry's batch log processor emits internal `BatchLogProcessor.ExportingDueToTimer` meta-events every second per Codex process. In measured high-fanout `logs_2.sqlite` databases, low-level `opentelemetry_sdk` events accounted for over 30% of retained rows (30-60% on the machines of people I asked to check). Persisting this SDK bookkeeping across many processes adds substantial write volume and contention without representing application activity. ## Validation - `just test -p codex-state` (132/132 tests passed, plus bench smoke) - `just fix -p codex-state` - `just fmt` --- codex-rs/state/src/log_db.rs | 15 +++++++ codex-rs/state/src/log_db_filter_tests.rs | 53 +++++++++++++++++++++++ 2 files changed, 68 insertions(+) create mode 100644 codex-rs/state/src/log_db_filter_tests.rs diff --git a/codex-rs/state/src/log_db.rs b/codex-rs/state/src/log_db.rs index 6024d6bda..71d2afbc0 100644 --- a/codex-rs/state/src/log_db.rs +++ b/codex-rs/state/src/log_db.rs @@ -189,6 +189,17 @@ where fn on_event(&self, event: &Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) { let metadata = event.metadata(); + // The SDK emits DEBUG timer meta-events every second per process; these + // were over 30% of retained logs in measured high-fanout Codex environments. + if metadata.target() == "opentelemetry_sdk" + && matches!( + *metadata.level(), + tracing::Level::TRACE | tracing::Level::DEBUG + ) + { + return; + } + let mut visitor = MessageVisitor::default(); event.record(&mut visitor); let thread_id = visitor @@ -451,6 +462,10 @@ impl Visit for MessageVisitor { } } +#[cfg(test)] +#[path = "log_db_filter_tests.rs"] +mod filter_tests; + #[cfg(test)] mod tests { use std::io; diff --git a/codex-rs/state/src/log_db_filter_tests.rs b/codex-rs/state/src/log_db_filter_tests.rs new file mode 100644 index 000000000..36ee27aba --- /dev/null +++ b/codex-rs/state/src/log_db_filter_tests.rs @@ -0,0 +1,53 @@ +use pretty_assertions::assert_eq; +use tracing_subscriber::filter::Targets; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; +use uuid::Uuid; + +use super::*; + +#[tokio::test] +async fn sqlite_sink_drops_low_level_opentelemetry_sdk_logs() { + let codex_home = + std::env::temp_dir().join(format!("codex-state-log-db-filter-{}", Uuid::new_v4())); + let runtime = StateRuntime::init(codex_home.clone(), "test-provider".to_string()) + .await + .expect("initialize runtime"); + let layer = start(runtime.clone()); + + let guard = tracing_subscriber::registry() + .with( + layer + .clone() + .with_filter(Targets::new().with_default(tracing::Level::TRACE)), + ) + .set_default(); + + tracing::trace!(target: "opentelemetry_sdk", "dropped-trace"); + tracing::debug!(target: "opentelemetry_sdk", "dropped-debug"); + tracing::info!(target: "opentelemetry_sdk", "retained-info"); + tracing::trace!(target: "codex_state", "retained-trace"); + + layer.flush().await; + drop(guard); + + let logs = runtime + .query_logs(&crate::LogQuery::default()) + .await + .expect("query logs after flush"); + assert_eq!( + logs.iter() + .map(|row| ( + row.level.as_str(), + row.target.as_str(), + row.message.as_deref() + )) + .collect::>(), + vec![ + ("INFO", "opentelemetry_sdk", Some("retained-info")), + ("TRACE", "codex_state", Some("retained-trace")), + ] + ); + + let _ = tokio::fs::remove_dir_all(codex_home).await; +}