第21章日志与追踪：QueryLogger、tracing span 与慢查询

"Observability is not a feature you add, it is a property of a system whose signals are already being recorded." —— Charity Majors，Observability Engineering

本章要点

sqlx 日志系统的核心是一个 170 行的文件——sqlx-core/src/logger.rs——结构体 QueryLogger<'q> + 配置 LogSettings + 两个跨 log/tracing 的宏 private_tracing_dynamic_enabled! / private_tracing_dynamic_event!。读懂这一个文件就读懂 sqlx 的全部日志机制。
LogSettings 三字段（sqlx-core/src/connection.rs:186-192）——statements_level: LevelFilter（默认 Debug）+ slow_statements_level: LevelFilter（默认 Warn）+ slow_statements_duration: Duration（默认 1s）——这套默认值意味着 sqlx 开箱即用就会把慢查询吼出来。
QueryLogger 的 5 个字段（logger.rs:63-69）——sql: &'q str + rows_returned: u64 + rows_affected: u64 + start: Instant + settings: LogSettings——它是一个挂在执行栈上的临时对象、不持有数据库连接、不 share 可变状态。
RAII 自动收口（logger.rs:161-165）——impl Drop for QueryLogger 在 drop 时调用 finish()——即使查询过程中抛出错误、日志也会被正确记录、不漏埋点。这是 Rust-only 的优雅设计。
private_tracing_dynamic_event! 的 5 分支 match（logger.rs:27-39）——因为 tracing issue #372——tracing::event!(target: ..., level, ...) 的 level 参数必须是编译期常量、不能运行时动态选择——sqlx 只能写成 match level { Level::ERROR => event!(ERROR, ...), ... }。
log + tracing 双轨兼容（logger.rs:101-106）—— sqlx 同时调用 log::log_enabled! 和 private_tracing_dynamic_enabled!、任一 enabled 就发事件——让只装了 log（没装 tracing subscriber）和只装了 tracing（没装 tracing-log）的用户都能看到日志。
target = "sqlx::query" 是所有查询事件的 target —— 用 tracing_subscriber::EnvFilter / env_logger / fern 过滤时、用这个字符串定位 sqlx 的查询日志。
target = "sqlx::postgres::notice" 是 Postgres NOTICE 消息的 target（sqlx-postgres/src/connection/stream.rs:178）——所有 RAISE NOTICE / RAISE WARNING / RAISE EXCEPTION 都通过这个 target 流过来、严重级别按 PgSeverity 映射。
慢查询判定（logger.rs:93-99）——let was_slow = elapsed >= self.settings.slow_statements_duration——然后在事件里附加 slow_threshold 字段 + 消息里硬编码字符串 "slow statement: execution time exceeded alert threshold"——设计让你 grep "slow" 就能找。
事件字段 schema——summary（SQL 前 4 词）+ db.statement（完整 SQL、长查询才带）+ rows_affected + rows_returned + elapsed（Debug 形式、带单位）+ elapsed_secs（f64、方便聚合）——slow_threshold 只在 slow 事件里附加。
连接/获取/迁移各有 tracing 事件——sqlx-postgres/src/connection/describe.rs:434、sqlx-postgres/src/options/pgpass.rs:48-73、sqlx-postgres/src/advisory_lock.rs:348 等都通过 tracing:: 宏发事件、生产调试链路不只有查询日志。

21.1 可观测性三要素与 sqlx 的定位

开始源码阅读之前、先定一下整章的框架——"可观测性"到底意味着什么、sqlx 在其中扮演什么角色。

业界的三支柱：

Metrics（指标）——Counter、Gauge、Histogram——聚合数据、回答"系统总体状态如何"。生态代表：Prometheus + Grafana。
Logs（日志）——结构化事件——回答"某次具体事件发生了什么"。生态代表：ELK、Loki、Datadog。
Traces（追踪）——分布式链路——回答"一次请求穿过了哪些服务、每步花了多久"。生态代表：Jaeger、Tempo、OpenTelemetry。

sqlx 只做 Logs 和 Traces——不自己产出 Metrics（不内置 Prometheus endpoint）——但通过 tracing 产出的结构化事件、可以被下游 subscriber 聚合成 Metrics（例如 tracing-metrics、opentelemetry-otlp → Prometheus exporter）。

这是一个重要的设计选择——sqlx 不强制绑定任何 metrics 后端、而是产出原始信号、让用户决定如何聚合。好处：

不给不需要的用户增加依赖——写个脚本直接用 sqlx 的人不需要 Prometheus。
不绑架后端——用 Datadog 的团队和用 Prometheus 的团队都能接得上。
保持 crate 轻量——sqlx 核心 crate 不拉几十个 metrics 依赖。

这个"只产原始信号"的定位让 sqlx 可观测性系统简单可控——整个实现一个文件、170 行——本章的主要篇幅就是逐字拆解这个文件。

这张图是本章的地图——左边是 sqlx 内部、右边是用户配置的 observability 栈。后续 32 个小节就是把这张图上每条边拆清楚。

21.2 LogSettings 的三个字段

源码（sqlx-core/src/connection.rs:186-202）：

rust

#[derive(Clone, Debug)]
#[non_exhaustive]
pub struct LogSettings {
    pub statements_level: LevelFilter,
    pub slow_statements_level: LevelFilter,
    pub slow_statements_duration: Duration,
}

impl Default for LogSettings {
    fn default() -> Self {
        LogSettings {
            statements_level: LevelFilter::Debug,
            slow_statements_level: LevelFilter::Warn,
            slow_statements_duration: Duration::from_secs(1),
        }
    }
}

逐字段解读：

`statements_level: LevelFilter`

所有 SQL 执行的默认日志级别。默认 Debug——意味着生产上用 info 或更高级别跑时、所有普通查询被过滤掉、不会刷屏日志。开发时调成 info 能看见每条 SQL、抓问题方便。

调整方式：

rust

use sqlx::ConnectOptions;
use log::LevelFilter;

let opts = PgConnectOptions::new()
    .host("localhost")
    .log_statements(LevelFilter::Info);

.log_statements() 在 ConnectOptions trait（connection.rs:254-255）上、每家驱动的 PgConnectOptions / MySqlConnectOptions / SqliteConnectOptions 都实现它。背后改的就是 LogSettings.statements_level 字段。

`slow_statements_level: LevelFilter`

慢查询（elapsed >= slow_statements_duration）的日志级别——默认 Warn。默认策略让慢查询自动浮现到 Warn 级别——用户不需要手动配、打开 Warn 级别的日志就能看到。

`slow_statements_duration: Duration`

慢查询阈值——默认 Duration::from_secs(1)——即 1 秒以上的 query 被标记为 slow。

调整：

rust

let opts = PgConnectOptions::new()
    .log_slow_statements(LevelFilter::Warn, Duration::from_millis(500));

这里 .log_slow_statements(level, duration) 是一个"两参数一起设"的 API——因为修改阈值大概率也要修改级别、合并成一个调用减少用户心智负担。

`#[non_exhaustive]` 的意义

LogSettings 打了 #[non_exhaustive]——意思是外部不能 direct 构造 LogSettings { ... }——必须用 LogSettings::default() 或通过 log_statements() / log_slow_statements() 修改。好处：

未来加字段不是 breaking change——加一个 redact_secrets: bool 不会挂现有代码。
强制通过 setter 方法配置——防止用户直接访问字段、绕过 API 语义检查。

这个小 attribute 体现 sqlx 团队对长期兼容性的关注——API 设计的深度功夫在未来的扩展方向。

21.3 QueryLogger 结构体

源码（logger.rs:63-80）：

rust

pub struct QueryLogger<'q> {
    sql: &'q str,
    rows_returned: u64,
    rows_affected: u64,
    start: Instant,
    settings: LogSettings,
}

impl<'q> QueryLogger<'q> {
    pub fn new(sql: &'q str, settings: LogSettings) -> Self {
        Self {
            sql,
            rows_returned: 0,
            rows_affected: 0,
            start: Instant::now(),
            settings,
        }
    }
    ...
}

关键观察：

生命周期 'q——QueryLogger 借用调用方传进来的 SQL 字符串、不拥有。这让 QueryLogger 零拷贝——执行 5000 字符的 SQL 不需要复制。
start: Instant——构造时立刻调用 Instant::now()、记录起始时间。构造即开始计时——不需要用户手动 start_timer()。
settings: LogSettings——owned（Clone），不是引用。理由：LogSettings 很小（两个 LevelFilter + 一个 Duration = ~16 字节）、clone 成本可忽略、owned 避免和连接对象的生命周期纠缠。
没有 &mut Connection 之类的字段——QueryLogger 和连接完全解耦、只关注"这次 query 的日志元数据"。

为什么不用 &LogSettings 而用 owned clone？

想象一下：每次 query 都要创建一个 QueryLogger、每个 logger 借用同一个 Connection 里的 log_settings——编译期可行但生命周期复杂：QueryLogger 必须和 Connection 的生命周期挂钩。而 clone 一份 LogSettings——16 字节 memcpy——生命周期彻底解耦、代码简单 10 倍。这是用少量性能换可读性的典型决策。

21.4 finish() 的控制流

源码（logger.rs:90-158）：

rust

pub fn finish(&self) {
    let elapsed = self.start.elapsed();
    let was_slow = elapsed >= self.settings.slow_statements_duration;

    let lvl = if was_slow {
        self.settings.slow_statements_level
    } else {
        self.settings.statements_level
    };

    if let Some((tracing_level, log_level)) = private_level_filter_to_levels(lvl) {
        let log_is_enabled = log::log_enabled!(target: "sqlx::query", log_level)
            || private_tracing_dynamic_enabled!(target: "sqlx::query", tracing_level);
        if log_is_enabled {
            // ... 发事件
        }
    }
}

控制流拆解：

计算耗时——self.start.elapsed() 返回 Duration。
判断是否慢查询——比较 elapsed 和 settings.slow_statements_duration。
选级别——慢查询用 slow_statements_level、否则用 statements_level。
private_level_filter_to_levels(lvl)——把 log::LevelFilter（用户 API 的输入类型）同时转换为 tracing::Level 和 log::Level（两个 crate 的 "有效" 级别类型）——如果输入是 LevelFilter::Off 返回 None、直接跳过后续所有逻辑。零开销路径。
双向 enabled 检查——log::log_enabled! 问 log crate、private_tracing_dynamic_enabled! 问 tracing crate——只要任一说"我要关心这个级别"、就继续。
发事件——根据 was_slow 分支选择带 slow_threshold 的 slow 事件或普通事件。

为什么两个 crate 都要查 enabled？

用户的部署可能是以下三种之一：

只用 log——装了 env_logger / fern / simple_logger、没装 tracing-subscriber。tracing crate 的 enabled 始终是 false、只有 log 路径会触发。
只用 tracing——装了 tracing-subscriber、没装 tracing-log（tracing 到 log 的桥接）。log crate 的 enabled 始终是 false、只有 tracing 路径会触发。
同时用两套——装了 tracing-log 做桥接——两边都 enabled、sqlx 只发一次（因为 event! 宏同时发到 log 和 tracing——tracing-log 自动转）。

双向检查确保任一配置都不漏日志。

21.5 private_tracing_dynamic_event! 的 5 分支 match

源码（logger.rs:27-39）：

rust

#[doc(hidden)]
#[macro_export]
macro_rules! private_tracing_dynamic_event {
    (target: $target:expr, $level:expr, $($args:tt)*) => {{
        use ::tracing::Level;

        match $level {
            Level::ERROR => ::tracing::event!(target: $target, Level::ERROR, $($args)*),
            Level::WARN => ::tracing::event!(target: $target, Level::WARN, $($args)*),
            Level::INFO => ::tracing::event!(target: $target, Level::INFO, $($args)*),
            Level::DEBUG => ::tracing::event!(target: $target, Level::DEBUG, $($args)*),
            Level::TRACE => ::tracing::event!(target: $target, Level::TRACE, $($args)*),
        }
    }};
}

为什么写成这么笨拙的 5 分支 match？

直接原因——tracing::event! 宏要求 Level 参数是编译期常量。你不能写：

rust

let level = ...; // 运行时值
tracing::event!(target: "x", level, "msg");  // ❌ 编译失败

深层原因——tracing crate 在 event! 展开时会根据 level 静态生成不同的 metadata——用于高性能的 dispatch::Event 构造。动态 level 意味着 metadata 不能在编译期确定、需要额外的堆分配和动态查表——会破坏 tracing 的 "零开销不启用事件" 承诺。

tracing 团队的决策——宁愿让动态级别的用户自己写 5 分支 match、也不给 static level 路径加开销——这是一个经典的 API 设计权衡：为主流场景优化、边缘用例用户自理。

sqlx 的应对——写成宏、hidden 掉（#[doc(hidden)]）、在 sqlx 内部用——用户看不到这个丑陋的 match、但享受 sqlx 的动态级别能力（用户可以配置 log_statements(LevelFilter::Trace) 或 LevelFilter::Error）。

注释里的链接：// https://github.com/tokio-rs/tracing/issues/372——tracing 社区长期存在的 issue——最终 tracing 团队也认为"写 5 分支"是可接受的工作区方案——没有把它当 bug 修、而是留了这个官方推荐的 workaround。

这个 5 分支 match 体现了系统库作者的克制——明明可以要求 tracing 团队加 API、但 sqlx 选择写 workaround——不强迫上游为自己改动、体现社区协作的成熟心智。

21.6 RAII Drop 自动收口

源码（logger.rs:161-165）：

rust

impl<'q> Drop for QueryLogger<'q> {
    fn drop(&mut self) {
        self.finish();
    }
}

三行代码——但设计含金量很高：

为什么用 Drop 而不是显式 `log.finish()`

假设你不用 Drop——sqlx 必须在每个 query 执行路径的结尾显式调用 logger.finish()——遇到提前返回（比如 SQL parse 失败）就容易漏。实际执行流：

rust

async fn run(&mut self, query: &str) -> Result<..., Error> {
    let mut logger = QueryLogger::new(query, settings);
    let prepared = self.prepare(query).await?;  // 可能失败提前 return
    let result = execute(prepared).await?;      // 可能失败提前 return
    logger.finish();  // ❌ 上面任一 ? 提前返回就漏了
    Ok(result)
}

用 Drop 就完全不一样——不管是正常 return、错误 ?、panic——drop 都会执行、日志都会收口。

rust

async fn run(&mut self, query: &str) -> Result<..., Error> {
    let mut logger = QueryLogger::new(query, settings);
    let prepared = self.prepare(query).await?;  // 提前返回 → drop → finish
    let result = execute(prepared).await?;      // 提前返回 → drop → finish
    Ok(result)  // 正常返回 → drop → finish
}

零出错可能性——RAII 的威力。

错误路径的日志也重要

你可能觉得"失败的 query 没必要记日志"——错——失败的 query 最需要日志：

生产出问题的 80% 都从失败查询开始调查。
慢到 timeout 的 query 你根本没看到返回、但 elapsed 已经累积了好几秒——RAII 保证这个慢 elapsed 必定被记录为 slow warning。
parse 错误的 SQL 虽然 rows_returned = 0、但 summary 里能看到用户想执行啥——排查客户端 bug 的线索。

RAII Drop 让 sqlx 的"失败查询也出日志" 成了免费特性——用户不需要任何配置、错误路径自动可观测。

Drop 的失败语义

Drop::drop 不能返回 Result——如果 finish() 内部 log 失败（磁盘满等）会怎样？

答：tracing::event! / log::log! 宏的实现不会 panic——内部用 catch_unwind 或类似机制保护。所以 Drop 里调 finish() 安全——即使日志系统挂了也不会把 query 的 drop 流程挂了。

这是生产级库的基本功——日志是增强、不应该把业务拖下水。

21.7 parse_query_summary 的 4 词截断

源码（logger.rs:167-173）：

rust

pub fn parse_query_summary(sql: &str) -> String {
    // For now, just take the first 4 words
    sql.split_whitespace()
        .take(4)
        .collect::<Vec<&str>>()
        .join(" ")
}

设计意图：

短 SQL（如 SELECT * FROM users）——4 词刚好或超了一点、summary 就是原 SQL。
长 SQL（带 CTE、JOIN、子查询、200 行）——截断到前 4 词、给人一个快速识别符——"哦这是个 INSERT INTO events"。

为什么恰好 4 词？

1 词（例如 SELECT）——信息太少、所有 SELECT 都分不开。
2 词（例如 SELECT *）——稍好、但看不到主表名。
3 词（例如 SELECT * FROM）——还是看不到表名。
4 词（例如 SELECT * FROM users）——基本够识别一次查询了。
10 词——太长、占日志行宽——何况完整 SQL 在 db.statement 字段里、summary 只是索引。

4 是实验出来的甜蜜点——注释里留了 // For now, just take the first 4 words 的口风——将来可能改——但实际上从 0.4 版本到 0.8 版本都是 4、生态已经习惯了。

空白符分割（split_whitespace）——Unicode-aware、能处理 tab / newline / 全角空格——SQL 里可能混入各种怪字符、用 Unicode 分割器避免意外。

21.8 事件字段的命名约定

sqlx 产出事件时附带一套标准化字段（logger.rs:125-155）：

rust

private_tracing_dynamic_event!(
    target: "sqlx::query",
    tracing_level,
    summary,
    db.statement = sql,
    rows_affected = self.rows_affected,
    rows_returned = self.rows_returned,
    ?elapsed,
    elapsed_secs = elapsed.as_secs_f64(),
    slow_threshold = ?self.settings.slow_statements_duration,
    "slow statement: execution time exceeded alert threshold"
);

字段释义：

`summary`

4 词 SQL 摘要——用于日志行可读。

`db.statement`

完整 SQL（只有在 summary 不等于 SQL 时才填、防止重复占带宽）。字段名 db.statement 是 OpenTelemetry 语义约定的标准字段——生产接 OTLP 的团队可以直接把这个字段映射到 span attribute——符合 OTel spec。

这个字段命名体现 sqlx 对生态标准的遵循——不自创 sql_string / query_text——而是用 OpenTelemetry 的 db.statement——和全行业对齐。

`rows_affected` / `rows_returned`

U64 计数。affected = UPDATE/DELETE/INSERT 影响的行数（execute 语义）、returned = SELECT 返回的行数（fetch 语义）。两者独立——同一个 RETURNING 查询可能两边都有值。

`elapsed` / `elapsed_secs`

两个字段表达同一个信息——Duration 形式（带单位、人类友好）和 f64 秒（数值、机器友好）。

为什么要两个？

?elapsed——Debug 格式化、输出 "321.45ms" 或 "2.3s"——人类看日志直接读。
elapsed_secs——纯数字、接到 metrics pipeline 里可以直接聚合——histogram(elapsed_secs) 算 p50/p99、不需要正则解析字符串。

两个字段各服务一种消费场景——是 Charity Majors 在 Observability Engineering 里推崇的"为消费者优化字段"思路。

`slow_threshold`

只在 slow 事件里附加——给运维提供"阈值是多少"的上下文——方便在 Datadog/Grafana 面板里设置告警阈值。

JSON 日志里看到 slow_threshold 字段出现就知道这是条慢查询告警——字段本身就是语义——比消息文本更稳定（消息文本可能被 i18n）。

消息文本

"slow statement: execution time exceeded alert threshold"

故意用 slow 一词——因为运维最常 grep slow 找慢查询告警——sqlx 对齐这个运维肌肉记忆。

普通事件没有 message（只有 fields）——因为 summary + db.statement 已经把 "是什么查询" 说清楚了——加消息反而冗余。

21.9 target 约定与过滤

sqlx 用两个稳定的 target：

sqlx::query（logger.rs:104-105）——所有查询事件（普通 + 慢查询）。
sqlx::postgres::notice（sqlx-postgres/src/connection/stream.rs:178）——Postgres NOTICE/WARNING 消息（RAISE 触发）。

target 是 tracing 和 log 的模块标识——用户过滤用。典型配置：

rust

// tracing_subscriber - EnvFilter
use tracing_subscriber::EnvFilter;
tracing_subscriber::fmt()
    .with_env_filter(
        EnvFilter::new("info,sqlx::query=debug,sqlx::postgres::notice=info")
    )
    .init();

字符串语义：

info —— 全局 INFO 级别。
sqlx::query=debug —— sqlx 查询事件降级到 DEBUG——开发时能看见每条 SQL。
sqlx::postgres::notice=info —— Postgres NOTICE（RAISE NOTICE 'foo'）按 INFO 输出。

env_logger 的配置类似：

rust

env_logger::Builder::from_env(env_logger::Env::default())
    .filter_module("sqlx::query", log::LevelFilter::Debug)
    .init();

target 命名风格——用 :: 分隔（Rust 风格）、小写——和 Rust 模块路径一致——符合 tracing 的默认 target 是 module_path!() 的约定（sqlx 手动指定为这两个字符串、让生产过滤比模块路径更稳定——即使 sqlx 内部重构模块、target 不变）。

21.10 log / tracing 两个 crate 的历史

为什么 sqlx 要同时支持 log 和 tracing？源于 Rust 生态的两代日志库的历史：

log crate（2014 起）——类似 C 的 syslog——级别 + 消息字符串——简单、全生态使用。log::info!("msg")。
tracing crate（2019 起）——带结构化字段 + span 传播——适合异步、适合分布式——tokio 系主推。tracing::info!(field = value, "msg")。

2020-2025 期间 Rust 社区处于"两套并存"的转换期：

老代码、同步程序—— log 占主流。
新代码、异步 + 分布式—— tracing 占主流。
大量生产代码两套都装、用 tracing-log 桥接。

sqlx 作为一个被广泛依赖的底层库——不能假设用户用哪一套——所以两边都发。付出的代价：多几行代码、logger.rs 里多一次 enabled 检查——值。

如果只支持 tracing——用 log 的团队就得先装 tracing 适配、才能看日志——增加采用成本。

如果只支持 log——tracing 生态的结构化字段优势发挥不出——span 传播断链。

两个都发 是 sqlx 的唯一正确选择——符合 "不把生态割裂压给用户" 的设计哲学。

21.11 QueryLogger 在驱动里的使用

三家驱动的 executor.rs / execute.rs 都按相同模式使用：

Postgres（sqlx-postgres/src/connection/executor.rs:205）：

rust

let mut logger = QueryLogger::new(query, self.inner.log_settings.clone());
// ... 循环处理 BackendMessage
//     logger.increase_rows_affected(rows_affected);
//     logger.increment_rows_returned();
// drop logger → finish → 日志发出

MySQL（sqlx-mysql/src/connection/executor.rs:109）：

rust

let mut logger = QueryLogger::new(sql, self.inner.log_settings.clone());
// ... OK Packet → rows_affected, ResultSet → rows_returned
// logger.increase_rows_affected(...); logger.increment_rows_returned();

SQLite（sqlx-sqlite/src/connection/execute.rs:30）：

rust

let logger = QueryLogger::new(query, conn.log_settings.clone());
// 写进 StatementWorker 任务里
// 执行时 self.logger.increment_rows_returned(); self.logger.increase_rows_affected(...);

统一的模式：

query 开始前 new 一个 logger。
执行循环里 increment / increase。
函数结束（正常或 ?）logger drop → finish → 日志出。

三家都复用 sqlx-core/logger.rs —— 证明这个 API 的抽象设计合适。

21.12 连接级 tracing 事件

除了 query 日志、sqlx 还在连接和迁移过程里直接用 tracing:: 宏发事件——不走 QueryLogger、不受 LogSettings 控制。

例子：

pgpass 文件读取（sqlx-postgres/src/options/pgpass.rs:48）：

rust

tracing::debug!("read pgpass from {:?}", path);

找不到密码文件时 warn——帮用户诊断 "为啥连不上 DB"。

describe 查询（sqlx-postgres/src/connection/describe.rs:434）：

rust

tracing::debug!(
    "described type: {:?} → {:?}",
    type_name, resolved_type
);

describe() 是 query!() 宏用来拿 SQL schema 的——debug 日志能帮调试"为啥我的 query!() 宏报错说列不存在"。

advisory_lock（sqlx-postgres/src/advisory_lock.rs:348）：

rust

tracing::warn!(...);

adv_lock 获取超时或释放失败时 warn——这些都是严重事件、值得生产告警。

Postgres NOTICE（stream.rs:178-190）——每个 RAISE NOTICE / RAISE WARNING 都走 target: "sqlx::postgres::notice"——让用户能把 DB 端的 RAISE 消息导出到日志。

这些"非 query"事件通常用 debug 或 warn——数量少、可以开着——帮诊断但不刷屏。

21.13 LevelFilter vs Level 的类型分工

读源码时会看到两个类型来回切换：

log::LevelFilter——包含 Off + 五个级别——用于配置（"我要记录到哪个级别为止"）。默认 Debug 意思是"Debug 及以上都记"。
log::Level / tracing::Level——只有五个级别（无 Off）——用于具体事件（"这个事件是 Info 级"）。

sqlx 用户 API（log_statements(LevelFilter::Info)）接受 LevelFilter——可以 Off 关掉日志。

sqlx 内部事件生成（event!(Level::Info, ...)）用 Level——具体级别。

中间的转换函数（logger.rs:42-55）：

rust

pub fn private_level_filter_to_levels(
    filter: log::LevelFilter,
) -> Option<(tracing::Level, log::Level)> {
    let tracing_level = match filter {
        log::LevelFilter::Error => Some(tracing::Level::ERROR),
        // ... 其余四个
        log::LevelFilter::Off => None,
    };
    tracing_level.zip(filter.to_level())
}

关键细节：

LevelFilter::Off 返回 None——表达"这个级别下不需要任何日志"的语义。
其余五个都 Some((tracing_level, log_level))——两套类型一起返回。
用 Option::zip 合并两个 Option——Rust stdlib 的小工具、代码简洁。

这个函数被调用一次就省下了两次 match——体现类型复用的惯用法。

21.14 零开销不启用的保证

sqlx 日志系统的一个重要承诺——不启用时零开销。怎么做到？

开销来源：

QueryLogger::new(...)——栈上分配 ~40 字节、Instant::now() 一次系统调用（vDSO，~20ns）。小但不是零。
increment_rows_returned / increase_rows_affected——原子计数——零到 1ns。
finish() 里的判断——如果 LevelFilter::Off、private_level_filter_to_levels 返回 None、后续全部跳过——零开销。
finish() 里 enabled 检查——log_enabled! 和 tracing::enabled! 都是极快的查询——~3ns。

总开销——query 不启用日志时 ~20ns（Instant::now() 主导）。query 执行时间至少 us 级别（本地 DB）或 ms 级别（远程 DB）——相对 20ns 完全可忽略。

启用日志时——还要 format 字符串、push 到 buffer、发到 subscriber——这部分开销和 log crate / tracing crate 的实现有关、不是 sqlx 控制的——但 sqlx 不额外加开销。

优化细节：

QueryLogger 的 settings.clone()——3 个字段的浅 copy（两个 LevelFilter 是 Copy、一个 Duration 也是 Copy）——优化成 memcpy、比想象中的 "clone" 便宜得多。
Instant::now() 在 macOS/Linux 上走 vDSO、不进内核——~20ns。
parse_query_summary 只在事件 enabled 之后才调用——没人消费就不浪费。

这些小优化叠加让 sqlx 日志路径在关闭和打开时都是生产可用的——关闭时可忽略、打开时可控。

21.15 tracing span 的生命周期与 sqlx

sqlx 内部没有 #[instrument] 或 tracing::info_span!("query") 风格的显式 span——查询事件是裸 event（点事件），不是 span（持续区间）。

为什么？

Span 的适用场景——一个有明确开始和结束的作业——user request、HTTP call、transaction。事件发生在 span 里。
sqlx query——一次调用快则 microseconds、慢则 seconds——很短——不值得开 span。而且每次 query 都开 span 会膨胀 trace 数据（trace-heavy 系统里一个 req 可能有几十次 DB query、span 数目爆炸）。

sqlx 的选择——不开 span、只发事件——让用户在自己的 span 里看到这些事件（query event 会被自然地关联到当前上下文的 span）：

rust

#[tracing::instrument]
async fn get_user_profile(id: UserId) -> Result<Profile> {
    let row = sqlx::query_as!("SELECT * FROM profiles WHERE id = $1", id)
        .fetch_one(&pool)
        .await?;
    Ok(row.into())
}

这段代码的效果：

#[instrument] 创建一个名为 get_user_profile 的 span、字段包含 id。
sqlx::query_as! 内部执行时、调用 logger.finish() 发 tracing event——这个 event 自动归属到 get_user_profile span（tracing 的 span 上下文机制）。
最终 Jaeger 里看到一个 get_user_profile span、里面有一个 "query: SELECT * FROM profiles" 事件——父子关系自然。

用户控制 span 粒度——sqlx 不强加——符合 "每层自己的职责" 原则。

21.16 tokio 和 tracing span 传播

tracing span 的"自动关联"在 tokio 里怎么实现？简要：

tracing::Span 内部是一个 ID + subscriber 管理的 metadata。
当进入一个 span（span.enter() 或 #[instrument]）、tracing 会把 span ID push 到当前线程的 thread-local stack。
tracing::event! 触发时、查这个 stack、拿到 "当前 span"、作为 event 的 parent。
async 跨 await 点——span 如果不 explicit 处理会丢。tracing::Instrument::instrument 把 span 绑到 Future 上、await 切换时 tracing 自动切 stack。

sqlx 在异步路径上——每个 query 都经过多个 await 点（send query、recv response）——tracing 的 Instrument 保证 span 在 await 前后一致——所以 logger.finish() 发 event 时、stack 顶还是业务 span——event 归属正确。

这是 tracing 的魔法——sqlx 不需要做任何事、自动享受。

21.17 从开发到生产的 subscriber 配置

开发环境——用 tracing_subscriber::fmt、彩色 + 人类可读：

rust

use tracing_subscriber::{fmt, EnvFilter};

tracing_subscriber::fmt()
    .with_env_filter(
        EnvFilter::try_from_default_env()
            .unwrap_or_else(|_| EnvFilter::new("info,sqlx::query=debug"))
    )
    .with_target(true)
    .with_thread_ids(true)
    .init();

日志输出样例：

2026-04-24T10:23:45Z DEBUG ThreadId(12) sqlx::query: summary="SELECT * FROM users" rows_returned=42 elapsed=3.2ms
2026-04-24T10:23:47Z WARN  ThreadId(15) sqlx::query: summary="UPDATE orders SET …" slow_threshold=1s elapsed=1.5s rows_affected=1000 slow statement: execution time exceeded alert threshold

生产环境——用 JSON 输出 + 接 OTLP：

rust

use tracing_subscriber::fmt::format::FmtSpan;

tracing_subscriber::fmt()
    .json()
    .with_env_filter(EnvFilter::from_default_env())
    .with_span_events(FmtSpan::CLOSE)
    .with_current_span(true)
    .init();

JSON 输出 sample：

json

{
  "timestamp": "2026-04-24T10:23:47Z",
  "level": "WARN",
  "target": "sqlx::query",
  "fields": {
    "summary": "UPDATE orders SET …",
    "db.statement": "\n\nUPDATE orders SET status = $1 WHERE created_at < $2\n",
    "rows_affected": 1000,
    "rows_returned": 0,
    "elapsed": "1.5s",
    "elapsed_secs": 1.523,
    "slow_threshold": "1s",
    "message": "slow statement: execution time exceeded alert threshold"
  },
  "span": {
    "name": "bulk_update_orders",
    "request_id": "req_abc123"
  }
}

这个 JSON 包含：

事件本身——level、target、fields。
Span 上下文——request_id = req_abc123——ELK/Loki 里按 request_id 搜能拿到完整链路。
OTel 语义字段——db.statement——直接可被 OTLP 解析。

生产配置要点：

JSON 而不是文本——结构化才能被 Loki/Datadog 正确索引。
.with_current_span(true)——把父 span 字段塞到 event 里——跨服务 join 的关键。
EnvFilter 从 env——运维可以 RUST_LOG=info,sqlx::query=debug 在线调级别、不用重启。

21.18 接 OpenTelemetry

生产更高级的做法——接 OTLP（OpenTelemetry Protocol）直接到 Jaeger / Tempo / Datadog：

rust

use opentelemetry::global;
use opentelemetry_otlp::WithExportConfig;
use tracing_subscriber::layer::SubscriberExt;

let tracer = opentelemetry_otlp::new_pipeline()
    .tracing()
    .with_exporter(
        opentelemetry_otlp::new_exporter()
            .tonic()
            .with_endpoint("http://otel-collector:4317"),
    )
    .install_batch(opentelemetry_sdk::runtime::Tokio)?;

let telemetry = tracing_opentelemetry::layer().with_tracer(tracer);
let subscriber = tracing_subscriber::Registry::default()
    .with(tracing_subscriber::EnvFilter::from_default_env())
    .with(telemetry)
    .with(tracing_subscriber::fmt::layer());

tracing::subscriber::set_global_default(subscriber)?;

这套接上后——每次 sqlx query 都会自动出现在 OTLP trace 里——作为 event、归属到 "外层业务 span"。在 Jaeger UI 里看到：

req_abc123 (800ms)
├── get_user_profile (15ms)
│   └── [event] summary="SELECT * FROM profiles" elapsed=3ms
├── check_permissions (20ms)
│   └── [event] summary="SELECT perm FROM roles" elapsed=2ms
└── bulk_update_orders (750ms)
    └── [event] summary="UPDATE orders SET …" elapsed=745ms slow=true

每一层 span 下面挂着 sqlx 的 query event——直接能看出哪个 span 对应哪条 SQL——调优生产慢 req 的黄金工具。

21.19 SQL 脱敏的现状

sqlx 没有内置 SQL 脱敏——这是一个重要的安全警告：

风险——你的 SQL 可能有字面量带敏感数据：

rust

sqlx::query("SELECT * FROM users WHERE email = 'admin@company.com'")
    .execute(&pool).await?;

sqlx 日志会记录 db.statement = "SELECT * FROM users WHERE email = 'admin@company.com'" —— 邮箱泄漏到日志里。同理密码、token、PII。

正确做法——永远用参数化：

rust

sqlx::query("SELECT * FROM users WHERE email = $1")
    .bind(email)
    .execute(&pool).await?;

sqlx 的日志只记录 SQL 模板（SELECT * FROM users WHERE email = $1）、参数值不记录（bind 的值不经过 QueryLogger）——这是 sqlx 的默认脱敏。

所以——参数化是正确性 + 安全 + 可观测性的三重保障。本书第 5、6、9 章反复强调 Arguments/Encode/bind——不是为了美观、是生产安全。

即使如此——有些系统还是担心 SQL 模板里也可能有敏感标识符（SELECT * FROM payments_2024_q1 暴露业务结构）——可以在 subscriber 里加字段脱敏 layer：

rust

use tracing_subscriber::filter::FilterFn;

let redact = FilterFn::new(|metadata| {
    metadata.target() != "sqlx::query"
        || !contains_sensitive(metadata.fields())
});

或者用 tracing-redact 类型的 third-party crate 做字段级脱敏。

sqlx 不提供是因为——脱敏规则团队有差异（邮箱可记 vs 不可记、UUID 可记 vs masked）——强制一套规则反而限制——把安全策略留给运维层 是正确选择。

21.20 log_statements(Off) 关闭日志

生产有一种场景——完全关闭查询日志、只保留 error/panic：

rust

let opts = PgConnectOptions::new()
    .log_statements(LevelFilter::Off)
    .log_slow_statements(LevelFilter::Off, Duration::default());

或者一句话：

rust

let opts = PgConnectOptions::new()
    .disable_statement_logging();

（connection.rs:262-265）

适用场景：

超高 QPS 系统（>10K QPS）——每条 query 一条 log 会压垮日志系统。
合规严格——PII 不能进日志——直接关了最保险。
有其他 APM 工具——Datadog APM agent 已经从网络抓 query、sqlx 日志重复。

关闭后——QueryLogger 还是会创建（Instant::now() 等还是执行）、只是 finish 时 private_level_filter_to_levels(Off) 返回 None、跳过事件发射——~20ns 的小开销、可忽略。

完全零开销需要 conditional compilation——sqlx 不提供 feature flag 编译去掉 logger——因为 20ns 在 query 的 ms 尺度上可忽略——为 20ns 引入 feature 复杂度不值。这是工程权衡。

21.21 log 后端的选择

env_logger——简单、从 env var 读配置——适合 CLI 和小服务：

rust

env_logger::Builder::from_default_env()
    .filter_module("sqlx::query", log::LevelFilter::Debug)
    .init();

fern——可 chain 多个 formatter + output——适合需要同时输出到文件和 stdout：

rust

fern::Dispatch::new()
    .format(|out, message, record| {
        out.finish(format_args!("[{}] {} {}", record.target(), record.level(), message))
    })
    .level(log::LevelFilter::Info)
    .level_for("sqlx::query", log::LevelFilter::Debug)
    .chain(std::io::stdout())
    .chain(fern::log_file("app.log")?)
    .apply()?;

simple_logger——最精简 2 行初始化——适合脚本。

tracing-log——把 log crate 的调用桥接到 tracing subscriber——混用两套时的胶水：

rust

tracing_log::LogTracer::init()?;

这行初始化后——所有 log::info! 都被 tracing subscriber 捕获——sqlx 的 log 路径和 tracing 路径汇合到一个 subscriber、避免看到重复日志。

21.22 慢查询告警的落地

sqlx 的慢查询事件是告警落地的起点：

最简单——grep 日志：

bash

tail -f app.log | grep 'slow statement'

进阶——Prometheus alert rule：

yaml

# prometheus-alerting-rules.yaml
groups:
- name: sqlx
  rules:
  - alert: SqlxSlowStatement
    expr: rate(sqlx_slow_statements_total[5m]) > 1
    for: 5m
    labels:
      severity: warning
    annotations:
      summary: "sqlx 慢查询告警"
      description: "过去 5 分钟 sqlx 慢查询速率 > 1/s"

这里的 sqlx_slow_statements_total 不是 sqlx 直接提供的——需要用户 subscriber 里累积——用 tracing-metrics 或自定义 layer：

rust

use tracing_subscriber::Layer;
use tracing::{Event, Metadata};

struct SlowQueryCounter;

impl<S> Layer<S> for SlowQueryCounter
where S: tracing::Subscriber {
    fn on_event(&self, event: &Event<'_>, _: tracing_subscriber::layer::Context<'_, S>) {
        if event.metadata().target() == "sqlx::query"
            && event_has_field(event, "slow_threshold")
        {
            SLOW_QUERY_COUNTER.inc();
        }
    }
}

SLOW_QUERY_COUNTER 是 Prometheus Counter——每次 slow query 触发——+1——Grafana 画曲线。

落地要点——sqlx 不做的是聚合、用户 subscriber 做——sqlx 做的是产出原始信号——分工清晰。

21.23 pool acquire 的日志

连接池获取也有日志——但默认较浅。pool 源码里没有显式 tracing::event!——依赖 QueryLogger 的事件序列（连接后会执行 ping query 等）来间接知晓。

真要看池获取慢——看 PoolOptions::after_connect 回调 + 自己在业务里 instrument：

rust

let pool = PgPoolOptions::new()
    .after_connect(|conn, _meta| Box::pin(async move {
        tracing::info!(
            "connection established, server_version={}",
            conn.server_version_num().unwrap_or(0)
        );
        Ok(())
    }))
    .connect(database_url).await?;

业务侧的 span 覆盖 .acquire() —— 看 span elapsed 就知道获取慢不慢：

rust

#[tracing::instrument]
async fn do_work(pool: &PgPool) -> Result<()> {
    let mut conn = pool.acquire().await?;
    // do_work span 的 elapsed 就包含了 acquire 时间
    sqlx::query!("...").execute(&mut *conn).await?;
    Ok(())
}

sqlx 不为 acquire 开 span 的原因——acquire 多数时候 sub-millisecond（池里有闲连接直接取走）——开 span 数据膨胀。真要 profile acquire 慢——用 Tokio console。

21.24 用 tokio-console 看连接池

tokio-console 是一个运行时调试工具——通过 tracing 接到进程里、UI 展示所有 Tokio task 的状态——包括 sqlx 连接池里的任务。

启用：

rust

console_subscriber::init();

启用后 connect cargo install tokio-console 安装的 console client——能看见：

pool 里每个连接是什么状态——idle / busy / closed。
task 卡在哪个 await 点——如果 query 卡在 recv_message、说明 DB 响应慢。
mutex / semaphore 的 waiter 数——池满了 waiter 排队多少。

tokio-console 和 sqlx 无需任何集成——tokio-console 从 tokio runtime 拿信号——sqlx 的任务自动可见。

生产建议——tokio-console 运行时开销不小（每个 await 都记录）、不要在生产开——开发 + staging 抓问题时开。

21.25 mermaid：日志系统的完整数据流

这张图说明 sqlx 日志从query 发起到可观测性后端的完整数据流。每一条边都可以在 sqlx-core/src/logger.rs 的代码里找到对应。

21.26 和 diesel、tokio-postgres 的日志对比

diesel——老牌同步 ORM。日志：

用 log crate（没有内建 tracing 支持）。
target 是 diesel::connection。
没有慢查询分级——所有 query 同一级别。
没有 rows_returned/rows_affected 字段。
结构化字段少——日志主要是字符串 message。

sqlx 相对 diesel 的优势：tracing 支持、慢查询分级、结构化字段——对生产可观测性友好。

tokio-postgres——更底层的 Postgres 客户端。日志：

用 log crate、有部分 tracing。
没有 slow query 概念。
基本只记"连接建立"、"连接断开"——query 级别默认不记。
用户要自己 wrap 记录 query。

sqlx 相对 tokio-postgres 的优势：开箱即用的 query-level 观测——不需要自己 wrap。

sqlx 的定位——介于 "自动但浅" 的 diesel 和 "什么都自己做" 的 tokio-postgres 之间——自动 + 可控——符合多数生产需求。

21.27 "sqlx::query" target 的稳定性承诺

这个 target 名称从 sqlx 0.3 版本就存在（可查 git history）、到 0.8 没变——说明 sqlx 团队把 target 名当成了公共 API。

这个约定隐含：

用户配置 sqlx::query=debug 的代码跨 sqlx 版本稳定。
即使 sqlx 内部重构（比如把 logger 搬到 sqlx-core/observability/ 子模块）——target 字符串不变。
Grafana dashboard / Datadog alert 基于 target:"sqlx::query" 的查询不需要重新配。

target 是"日志的命名空间"——和模块路径分离让它更稳定——这个设计细节见功夫。

类似约定——db.statement 字段名、slow statement message、slow_threshold 字段名——都是事实上的 sqlx 公共 API——运维团队基于这些建立仪表板和告警。

破坏这些约定就是破坏用户的生产告警——sqlx 团队知道这点、保持稳定。

21.28 常见误用和避坑

误用 1：日志级别开到 Trace 上生产

rust

.log_statements(LevelFilter::Trace)  // ⚠ 生产不要

Trace 级别连每条 query 都打——10K QPS 的服务能把日志系统炸掉。

正确——生产 LogSettings::default() 就好（Debug 级别、大多数 log backend 默认过滤 debug）。

误用 2：slow threshold 设得过小

rust

.log_slow_statements(LevelFilter::Warn, Duration::from_millis(10))  // ⚠

10ms threshold——几乎所有 query 都"慢"——告警风暴。

正确——threshold 应该是 99 分位的一半左右——如果 99 分位是 200ms、threshold 设 100ms 就合适。

误用 3：生产忘开 log/tracing subscriber

sqlx 日志发出来了、但没人消费——sqlx 发的事件到 tracing 全局 subscriber、如果没初始化 subscriber 就走 no-op subscriber——日志丢失。

正确——main 函数第一件事就是 init subscriber：

rust

fn main() -> Result<()> {
    tracing_subscriber::fmt().init();  // 必须在 sqlx 使用前
    // ...
}

误用 4：期待 sqlx 记录 bind 参数

rust

sqlx::query("SELECT * FROM users WHERE id = $1")
    .bind(user_id)  // ← 这个值不会出现在日志里
    .execute(&pool).await?;

日志只有 SQL 模板——bind 值不记——这是安全特性、不是 bug。想调试 bind 值——在业务代码里自己 tracing::info——sqlx 不管。

误用 5：QueryLogger 和 transaction 的关系

每次 query.execute() 都 new 一个 logger——一个 transaction 里 5 次 query 就有 5 个 logger 事件——不是"一个 transaction 一个事件"。

想要 transaction 级别的日志——自己 wrap：

rust

#[tracing::instrument]
async fn transfer_funds(pool: &PgPool, from: Id, to: Id, amount: Money) -> Result<()> {
    let mut tx = pool.begin().await?;
    sqlx::query!("UPDATE accounts SET balance = balance - $1 WHERE id = $2", amount, from)
        .execute(&mut *tx).await?;
    sqlx::query!("UPDATE accounts SET balance = balance + $1 WHERE id = $2", amount, to)
        .execute(&mut *tx).await?;
    tx.commit().await?;
    Ok(())
}

transfer_funds span 覆盖两条 query——日志层级清晰。

21.28a SQLite 的 ExecuteIter：logger 作为迭代器字段

SQLite 驱动的使用方式比 Postgres/MySQL 多一层——logger 被塞进一个结构体字段（sqlx-sqlite/src/connection/execute.rs:8-19）：

rust

pub struct ExecuteIter<'a> {
    handle: &'a mut ConnectionHandle,
    statement: &'a mut VirtualStatement,
    logger: QueryLogger<'a>,
    args: Option<SqliteArguments<'a>>,
    args_used: usize,
    goto_next: bool,
}

为什么 SQLite 特殊？

Postgres/MySQL——async I/O 模型——run() 函数体内 new logger、函数返回 drop——时机清晰。
SQLite——C FFI + blocking——executor 把执行拆成 ExecuteIter 迭代器、用户 .next() 逐步推进——logger 必须和迭代器生命周期一致。

实现——logger 作为 struct 字段——struct drop 时 logger drop——RAII 语义仍然满足——即使用户提前 break 掉迭代也会正确发日志。

这个灵活性——QueryLogger<'a> 作为字段还是局部变量都行——体现它设计时没有强绑任何使用模式——纯粹一个数据 + Drop 语义的小对象——到哪都能用。

小对比——如果 logger 要求"必须作为局部变量 new 并在函数结束 drop"、SQLite 的 ExecuteIter 就写不出来——sqlx 核心 API 的弱约束正好匹配三家驱动的异构执行模型——抽象做得漂亮。

21.28b tracing-log 桥接的时序细节

tracing-log crate 是生态里最常见的 log→tracing 胶水——但它的启用时机有坑。

正常流程：

main() 里第一件事：tracing_subscriber::fmt().init(); —— 初始化 tracing subscriber。
第二件事（关键）：tracing_log::LogTracer::init(); —— 把 log crate 的 "global logger" 设置为 tracing-log 的 bridge。
从此以后——所有 log::info!("msg") 被 tracing-log 捕获、转换为 tracing::event!(Level::INFO, message = "msg") 发到 tracing subscriber。

坑：如果步骤 2 没做——log crate 的 global logger 是 no-op——sqlx 的 log 路径发的事件都丢了。用户可能以为 tracing subscriber 会自动接住——不会。

怎么诊断这个坑：

打开 sqlx 的 log_statements—— 没看到日志——第一反应怀疑 sqlx——其实是 subscriber 没桥接。
解决：tracing_log::LogTracer::builder().init()?;

sqlx 的设计正是考虑到这个坑——同时发到 log 和 tracing——即使用户没装 tracing-log、也有其中一路能看到日志——双轨冗余是对用户的保护。

反面——如果 tracing-log 装了（桥接启用）——sqlx 同时发两份——会不会重复打印？

不会。tracing-log 默认只 handle log crate 的调用——不 handle tracing crate 自己的调用——所以 sqlx 的 tracing::event! 被 tracing subscriber 直接消费、log::log! 被 tracing-log 桥接成 tracing 事件再消费——两路同时到达 subscriber、subscriber 可能看到两份相同事件。

解决——sqlx 在 finish() 里只调一次宏——private_tracing_dynamic_event! 展开为 tracing::event!——这个宏同时发到 tracing 和 log（因为 tracing 有内置 log compatibility）——用户 subscriber 只收一份。

这个细节能看出 sqlx 团队对跨生态的细致把控——绝对值得背下来。

21.29 Postgres NOTICE 特殊路径

Postgres 的 RAISE NOTICE / RAISE WARNING / RAISE EXCEPTION 不走 QueryLogger——而是走 sqlx-postgres/src/connection/stream.rs:161-193 的单独路径。

事件 target——sqlx::postgres::notice。

级别映射（stream.rs:167-175）：

PgSeverity	log Level	tracing Level
Fatal / Panic / Error	Error	ERROR
Warning	Warn	WARN
Notice	Info	INFO
Debug	Debug	DEBUG
Info / Log	Trace	TRACE

事件字段——只有一个 message = notice.message()。

典型用法——你写存储过程：

sql

CREATE OR REPLACE FUNCTION process_batch(n INT)
RETURNS void AS $$
BEGIN
    IF n > 1000 THEN
        RAISE WARNING 'batch size % too large', n;
    END IF;
    -- ...
END;
$$ LANGUAGE plpgsql;

调用 SELECT process_batch(2000) —— Postgres 发 WARNING NoticeResponse —— sqlx 捕获 —— 日志里出现：

WARN sqlx::postgres::notice: message="batch size 2000 too large"

这是从 DB 端发到客户端日志的"带外通道"——和 query result 解耦——用来做软警告和调试信息——sqlx 正确地把它转成可观测日志。

21.29a 结构化字段 vs 字符串消息：一条血的教训

Rust 早期 log crate 的日志都是字符串消息——log::info!("user {} logged in from {}", user_id, ip)——生成一行格式化好的 string。

问题——这条日志进 ELK 之后、想按 user_id 聚合——必须用正则从字符串抠出 user_id——脆弱。改一下消息格式（比如加个逗号）—— 所有历史告警规则都要重写。

tracing 的改进——结构化字段——tracing::info!(user_id = %user_id, ip = %ip, "user logged in")——user_id 作为独立字段进 JSON 日志——ELK/Loki 原生索引、不用正则。

sqlx 的 logger.rs 是结构化日志的典范——每个字段独立：

rust

private_tracing_dynamic_event!(
    target: "sqlx::query",
    tracing_level,
    summary,                    // 字段
    db.statement = sql,         // 字段
    rows_affected = ...,        // 字段
    rows_returned = ...,        // 字段
    ?elapsed,                   // 字段
    elapsed_secs = ...,         // 字段
    slow_threshold = ?...,      // 字段
    "slow statement: ..."       // message 字符串（搜索友好）
);

消息字符串 + 结构化字段并存——消息让 grep 方便、字段让聚合方便——两全。

生产落地要点——用 JSON 输出（tracing_subscriber::fmt().json()）——字段原生进 JSON——不经过 string 中间层——字段类型保留（rows_affected 是 int、elapsed_secs 是 float）——Grafana 直接做数值运算：

sql

-- Loki LogQL
sum by(target) (rate({app="myapp", target="sqlx::query"} | json | elapsed_secs > 0.5 [5m]))

这个 LogQL 查询——"过去 5 分钟每秒多少条慢查询"——sqlx 的结构化日志直接支持。

结论——sqlx 日志生态成熟度高、因为它从一开始就选对了结构化——历史包袱少——这是后发优势。

21.30 设计哲学：产出信号，不定策略

读完 sqlx 日志系统让人印象最深的一点——sqlx 产出原始信号、不定聚合策略。

具体：

sqlx 不输出 Metrics（Counter/Gauge）——让用户 subscriber 做聚合。
sqlx 不绑定 Datadog / Prometheus / OTLP——用户自选后端。
sqlx 不做字段脱敏——用户根据合规要求自己做。
sqlx 不决定 slow threshold 对业务意味着什么——只记录事实。

这是库和应用的分工边界：

库：产出事实（elapsed = 1.5s、query = "UPDATE ...")。
应用：决定意义（1.5s 算慢吗？要告警吗？告警到哪？）。

违反这条边界的库（强绑定后端、强推聚合策略）——生态采用率低——用户嫌"你管太多"。

sqlx 严格守住这条边界——170 行代码 就把查询可观测性做到了生产级——体现了良好的抽象品味。

推广到 Rust 生态——tokio/hyper/reqwest 都类似——产出 tracing 事件、不绑定聚合后端——用户拼装——组合式优于继承式——小而精的库优于大而全的框架。

21.30a 一个典型场景：用 db.statement 字段追定位 N+1

来一个典型场景——说明 sqlx 日志字段的调试威力。下面是 N+1 查询问题在 sqlx 日志里暴露和定位的标准流程、任何 Rust Web 服务都可能遇到。

症状——API 列表接口 /api/orders p99 从 200ms 涨到 2s、持续两周、业务代码没动。

第一步：打开 sqlx query 日志

在 staging 环境临时把 sqlx::query 的 tracing filter 从 info 调到 debug：

RUST_LOG=info,sqlx::query=debug cargo run

模拟一次 /api/orders 调用、看日志。

第二步：发现异常

预期——这个接口应该只有 2-3 条 query（取订单列表 + 取订单项）。实际——日志里50 多条 summary="SELECT * FROM order_items"——每个订单触发一次查询——N+1 查询经典案例。

第三步：按 db.statement 字段聚合

把日志导到 Loki、查：

{app="api"} | json | target="sqlx::query" | line_format "{{.db_statement}}"
| summarize count() by db_statement

结果：

SELECT * FROM orders WHERE user_id = $1 ORDER BY created_at DESC
SELECT * FROM order_items WHERE order_id = $1   ← 触发了 47 次！
SELECT SUM(amount) FROM payments WHERE order_id = $1   ← 触发了 47 次！

问题定位清楚——ORDER.get_items() 和 ORDER.get_total() 在循环里一个个查。

第四步：修复

把 for order in orders { order.load_items(&conn).await?; } 改成一次 JOIN：

rust

let orders_with_items: Vec<OrderWithItems> = sqlx::query_as!(
    OrderWithItems,
    "SELECT o.*, array_agg(oi.*) as items
     FROM orders o
     LEFT JOIN order_items oi ON o.id = oi.order_id
     WHERE o.user_id = $1
     GROUP BY o.id
     ORDER BY o.created_at DESC",
    user_id
).fetch_all(&pool).await?;

结果——p99 从 2s 降到 150ms。

关键是 sqlx 的日志让问题可见——没有 db.statement 字段聚合能力、只有 count: 2s 的 query 这种粗粒度日志——根本定位不了是哪些 query 占时间。

这个流程的含义——sqlx 日志字段结构化的价值在出事时才体现——日常看起来多余的 7 个字段、出事时每一个都是定位线索。

这是投资可观测性的典型回报——平时看起来没用、出事时一小时解决 vs 一周摸索。

21.31 从三支柱回看 sqlx 可观测

回到章节开头的三支柱框架——看 sqlx 的贡献：

支柱	sqlx 贡献	配合方
Logs	QueryLogger 产出结构化事件	env_logger / tracing-subscriber
Traces	tracing event 归属 span	tracing-opentelemetry
Metrics	（不直接）产出事件给用户聚合	用户自定义 Layer / tracing-metrics

sqlx 主打 Logs + Traces——Metrics 通过 tracing 间接支持——三支柱各司其职。

完整可观测栈推荐——对于 Web 服务：

Logs——tracing_subscriber JSON + Loki。
Traces——tracing-opentelemetry + OTLP Collector + Tempo。
Metrics——自定义 Layer 累积到 Prometheus endpoint。

sqlx 全栈参与——每一层都有 sqlx 信号贡献——生产可观测性覆盖完整。

21.32 延伸思考题

留几个思考题给读者——对应本章核心设计决策：

为什么 QueryLogger 没持有 &Connection？
答：解耦。logger 只关心 SQL + 耗时 + 计数——不需要知道是哪条连接。将来连接换实现（比如 QUIC 替换 TCP）—— logger 不受影响。单一职责——logger 的职责就是记录查询元数据、不是管理连接。
为什么把 LogSettings clone 进 logger 而不是借用？
答：生命周期解耦。借用会让 logger 和 connection 的生命周期绑定——复杂。16 字节 clone——memcpy 比 Box 还快——性能零损失、可读性大幅提升。
为什么慢查询消息里硬编码 slow 这个词？
答：运维肌肉记忆。Linux sysadmin 遇到性能问题第一反应是 grep slow——sqlx 对齐这个 convention——减少用户学习成本、融入既有工作流。
为什么用 target = "sqlx::query" 而不是 module_path!() 的自动值？
答：稳定性。模块路径随重构变——sqlx_core::logger 和 sqlx_core::query::logger 可能变——手动固定 target 让用户配置跨版本稳定——target 是 API 的一部分。
sqlx 为什么没实现 #[instrument] 风格的 query span？
答：性能。query span 会给每次 query 开一个 span——高 QPS 服务 span 数据爆炸——违反 "观测不应拖性能" 原则。用event 而不是 span 是正确选择——span 由用户业务层控制粒度。

这些问题如果你都能回答——你已经掌握了 sqlx 日志系统的所有设计决策——这正是深度阅读源码的意义。

21.33 本章小结与下章预告

本章系统梳理 sqlx 的日志与追踪：

QueryLogger 的 5 个字段 + RAII Drop 收口。
LogSettings 的 3 个配置字段 + 默认值哲学。
private_tracing_dynamic_event! 的 5 分支 match 和 tracing issue #372 的工作区。
log + tracing 双轨发射、目标命名稳定。
事件字段 schema（summary、db.statement、rows_affected/returned、elapsed、slow_threshold）。
从开发到生产的 subscriber 配置演进（fmt → JSON → OTLP）。
tokio-console、慢查询告警、Postgres NOTICE 的完整落地方案。

下章第 22 章生产实战——把 21 章的所有内容整合到生产场景——展示真实问题的诊断流程和解决方案——全书的落地收官。

21.34 和《Tokio 源码深度解析》第17章的互参

sqlx 把 tracing event 归属到调用方 span、自己不开 query-level span——这个选择对应《Tokio 源码深度解析》第 17 章 §17.3 tracing：span 和 event 的双层模型——Tokio 那章详细讲了：

Span = 区间（enter/exit 配对）、Event = 点——两层模型的职责分工。
tracing 的 Instrument trait 把 span 绑到 Future 上、await 切换时 stack 自动同步——tokio::spawn(fut.instrument(span)) 是跨 task 保持 span 的官方姿势。
Tokio §17.4 讲 tokio-console —— 本章 §21.24 提到的 console_subscriber::init() 背后的 runtime 可观测机制——和 sqlx 无关但免费享受。

对照：

sqlx §21.15 "tracing span 的生命周期与 sqlx"↔《Tokio》§17.3 的两层模型——两本书从不同角度讲同一件事。
sqlx §21.24 "用 tokio-console 看连接池"↔《Tokio》§17.4 的 tokio-console 工具——sqlx 不做任何集成、直接受益。
sqlx §21.18 接 OpenTelemetry ↔《Tokio》§17.2 把 Metrics 连到 Prometheus——同一套 tracing → exporter 管线。

建议的阅读顺序——如果你先读了《Tokio》第 17 章——本章的 sqlx event 归属、span 传播、tokio-console 这些主题几乎无需再学；反过来读完本章再看《Tokio》第 17 章—— runtime 级别的可观测让你的诊断工具箱从"sqlx 日志"拓展到"整个 Tokio runtime"。两章合读完整。

第21章 日志与追踪：QueryLogger、tracing span 与慢查询 ​

21.1 可观测性三要素与 sqlx 的定位 ​

21.2 LogSettings 的三个字段 ​

statements_level: LevelFilter ​

slow_statements_level: LevelFilter ​

slow_statements_duration: Duration ​

#[non_exhaustive] 的意义 ​

21.3 QueryLogger 结构体 ​

21.4 finish() 的控制流 ​

21.5 private_tracing_dynamic_event! 的 5 分支 match ​

21.6 RAII Drop 自动收口 ​

为什么用 Drop 而不是显式 log.finish() ​

错误路径的日志也重要 ​

Drop 的失败语义 ​

21.7 parse_query_summary 的 4 词截断 ​

21.8 事件字段的命名约定 ​

summary ​

db.statement ​

rows_affected / rows_returned ​

elapsed / elapsed_secs ​

slow_threshold ​

消息文本 ​

21.9 target 约定与过滤 ​

21.10 log / tracing 两个 crate 的历史 ​

21.11 QueryLogger 在驱动里的使用 ​

21.12 连接级 tracing 事件 ​

21.13 LevelFilter vs Level 的类型分工 ​

21.14 零开销不启用的保证 ​

21.15 tracing span 的生命周期与 sqlx ​

21.16 tokio 和 tracing span 传播 ​

21.17 从开发到生产的 subscriber 配置 ​

21.18 接 OpenTelemetry ​

21.19 SQL 脱敏的现状 ​

21.20 log_statements(Off) 关闭日志 ​

21.21 log 后端的选择 ​

21.22 慢查询告警的落地 ​

21.23 pool acquire 的日志 ​

21.24 用 tokio-console 看连接池 ​

21.25 mermaid：日志系统的完整数据流 ​

21.26 和 diesel、tokio-postgres 的日志对比 ​

21.27 "sqlx::query" target 的稳定性承诺 ​

21.28 常见误用和避坑 ​

21.28a SQLite 的 ExecuteIter：logger 作为迭代器字段 ​

21.28b tracing-log 桥接的时序细节 ​

21.29 Postgres NOTICE 特殊路径 ​

21.29a 结构化字段 vs 字符串消息：一条血的教训 ​

21.30 设计哲学：产出信号，不定策略 ​

21.30a 一个典型场景：用 db.statement 字段追定位 N+1 ​

21.31 从三支柱回看 sqlx 可观测 ​

21.32 延伸思考题 ​

21.33 本章小结与下章预告 ​

21.34 和《Tokio 源码深度解析》第17章的互参 ​

第21章日志与追踪：QueryLogger、tracing span 与慢查询

21.1 可观测性三要素与 sqlx 的定位

21.2 LogSettings 的三个字段

`statements_level: LevelFilter`

`slow_statements_level: LevelFilter`

`slow_statements_duration: Duration`

`#[non_exhaustive]` 的意义

21.3 QueryLogger 结构体

21.4 finish() 的控制流

21.5 private_tracing_dynamic_event! 的 5 分支 match

21.6 RAII Drop 自动收口

为什么用 Drop 而不是显式 `log.finish()`

错误路径的日志也重要

Drop 的失败语义

21.7 parse_query_summary 的 4 词截断

21.8 事件字段的命名约定

`summary`

`db.statement`

`rows_affected` / `rows_returned`

`elapsed` / `elapsed_secs`

`slow_threshold`

消息文本

21.9 target 约定与过滤

21.10 log / tracing 两个 crate 的历史

21.11 QueryLogger 在驱动里的使用

21.12 连接级 tracing 事件

21.13 LevelFilter vs Level 的类型分工

21.14 零开销不启用的保证

21.15 tracing span 的生命周期与 sqlx

21.16 tokio 和 tracing span 传播

21.17 从开发到生产的 subscriber 配置

21.18 接 OpenTelemetry

21.19 SQL 脱敏的现状

21.20 log_statements(Off) 关闭日志

21.21 log 后端的选择

21.22 慢查询告警的落地

21.23 pool acquire 的日志

21.24 用 tokio-console 看连接池

21.25 mermaid：日志系统的完整数据流

21.26 和 diesel、tokio-postgres 的日志对比

21.27 "sqlx::query" target 的稳定性承诺

21.28 常见误用和避坑

21.28a SQLite 的 ExecuteIter：logger 作为迭代器字段

21.28b tracing-log 桥接的时序细节

21.29 Postgres NOTICE 特殊路径

21.29a 结构化字段 vs 字符串消息：一条血的教训

21.30 设计哲学：产出信号，不定策略

21.30a 一个典型场景：用 db.statement 字段追定位 N+1

21.31 从三支柱回看 sqlx 可观测

21.32 延伸思考题

21.33 本章小结与下章预告

21.34 和《Tokio 源码深度解析》第17章的互参