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

sqlx 的日志系统核心只有一个 173 行的文件：QueryLogger 记下 SQL、返回行数与起始时间，LogSettings 用两个 level 和一个阈值把普通语句和慢查询分开。

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（例如自定义 Layer 计数，见 §21.22）。

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

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

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

flowchart LR
    A[sqlx query 执行] --> B[QueryLogger 创建]
    B --> F[执行 + 计数 rows]
    F --> G[Drop 触发 finish]
    G --> H{elapsed 超阈值}
    H -->|否| I[取 statements_level<br/>默认 Debug]
    H -->|是| J[取 slow_statements_level<br/>默认 Warn]
    I --> C{级别非 Off 且<br/>log / tracing 任一 enabled}
    J --> C
    C -->|否| D[不发事件]
    C -->|是| E[tracing::event!]
    E --> L[tracing crate]
    L -->|已设置 tracing subscriber| N[tracing_subscriber 输出]
    L -->|未设置时由 log feature 转发| K[log crate]
    K --> M[env_logger / fern 输出]
    N --> O[Jaeger / OTLP / Datadog]

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

21.2 LogSettings 的三个字段

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

#[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、抓问题方便。

调整方式：

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

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

.log_statements() 在 ConnectOptions trait（sqlx-core/src/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。

调整：

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

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

#[non_exhaustive] 的意义

LogSettings 打了 #[non_exhaustive]——意思是在 sqlx-core 之外不能用结构体字面量 LogSettings { ... } 构造（实测报 error[E0639]: cannot create non-exhaustive struct using struct expression）——只能从 LogSettings::default() 出发，再用 log_statements() / log_slow_statements() 修改。好处：

• 未来加字段不是 breaking change——加一个 redact_secrets: bool 不会挂现有代码。

注意三个字段本身是 pub 的，拿到一个 LogSettings 仍可直接读写字段。只是各驱动的 XxxConnectOptions 把它存成 pub(crate) log_settings，用户实际只能通过 ConnectOptions 上的 log_statements / log_slow_statements / disable_statement_logging 三个方法去配置。

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

21.3 QueryLogger 结构体

源码（sqlx-core/src/logger.rs:63-80）：

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，全是 Copy）、clone 成本可忽略、owned 避免和连接对象的生命周期纠缠。
• 没有 &mut Connection 之类的字段——QueryLogger 和连接完全解耦、只关注"这次 query 的日志元数据"。

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

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

21.4 finish() 的控制流

源码（sqlx-core/src/logger.rs:90-158）：

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 {
            // ... 发事件
        }
    }
}

控制流拆解：

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

为什么两个 crate 都要查 enabled？

因为 "谁在收日志"这件事有两个独立的答案源，而 sqlx 事先不知道用户装的是哪一套：

• 只装了 log 后端（env_logger / fern / simple_logger），没装 tracing-subscriber：tracing::enabled! 会说 false（没有 subscriber），但 log::log_enabled! 说 true。
• 只装了 tracing-subscriber，没装 tracing-log：log::log_enabled! 说 false，tracing::enabled! 说 true。

源码注释把这层意思写得很直白：

The enabled level could be set from either tracing world or log world, so check both to see if logging should be enabled for our level

任一为真就往下走——确保任一配置都不漏日志。注意这只是"要不要发"的判断：真正发事件时 sqlx 只调 tracing::event! 一次，log 那一路靠 tracing 的 log feature 转发（详见 §21.30）。

21.5 private_tracing_dynamic_event! 的 5 分支 match

源码（sqlx-core/src/logger.rs:27-39）：

#[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 参数是常量。你不能写：

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

用 tracing 0.1.44 实测，报错是：

error[E0435]: attempt to use a non-constant value in a constant

深层原因——event! 展开时会生成一个 static __CALLSITE，事件的 Metadata（target、level、字段名）就存在这个 static 里；subscriber 对 callsite 的 interest 也按它缓存。level 是 static 初始化表达式的一部分，所以必须是常量。

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

注释里的链接：// https://github.com/tokio-rs/tracing/issues/372——这个 issue 标题是 "Dynamic level support"，2019 年 10 月提出，至今仍是 open 状态。上游没有提供动态 level 的 API 之前，按 level 展开 5 个分支是库作者能用的办法。

21.6 RAII Drop 自动收口

源码（sqlx-core/src/logger.rs:161-165）：

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

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

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

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

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 都会执行、日志都会收口。

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 最需要日志：

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

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

Drop 的失败语义

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

答：finish() 本身不返回 Result——它要么因为级别关闭直接跳过、要么把事件交给 tracing / log 的 subscriber。真正的写盘（或网络发送）发生在 subscriber 里，sqlx 管不着；如果某个 subscriber 实现自己 panic，那会在 drop 里 panic——这是 subscriber 的责任，不是 sqlx 的。sqlx 能保证的是：它自己这一段没有 unwrap()、没有可能失败的 I/O。

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

21.7 parse_query_summary 的 4 词截断

源码（sqlx-core/src/logger.rs:167-173）：

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，finish() 里 summary != self.sql 为假，db.statement 填空串。
• 其余 SQL（哪怕只多一个词，或者多了换行、连续空格）——summary 取前 4 词再加上 …，完整 SQL 放进 db.statement，给人一个快速识别符——"哦这是个 INSERT INTO events …"。

为什么恰好 4 词？

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

注释里留了 // For now, just take the first 4 words 的口风——将来可能改——0.8.6 里就是 4。

空白符分割（split_whitespace）——Unicode-aware、能处理 tab / newline / 全角空格（实测 "SELECT *\n FROM\tusers\u{3000}WHERE id = $1" 得到 "SELECT * FROM users"）——SQL 里可能混入各种怪字符、用 Unicode 分割器避免意外。

sequenceDiagram
    participant Caller as 调用方
    participant Logger as QueryLogger
    participant Log as log crate
    participant Tracing as tracing crate
    Caller->>Logger: new(sql, settings)
    activate Logger
    Note right of Logger: start = Instant::now()
    Caller->>Logger: increment_rows_returned()
    Caller->>Logger: increment_rows_returned()
    Caller->>Logger: increase_rows_affected(3)
    Caller->>Logger: (函数结束 / 错误 ?)
    Logger->>Logger: Drop::drop()
    Logger->>Logger: finish()
    Logger->>Logger: elapsed, was_slow?
    Logger->>Log: log_enabled?
    Logger->>Tracing: enabled?
    Note right of Logger: 任一 enabled 即发射<br/>唯一发射点是 tracing
    Logger->>Tracing: event!(level, summary, sql, rows, elapsed)
    Tracing-->>Log: 由 tracing 的 log feature 代发
    deactivate Logger

21.8 事件字段的命名约定

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

                    private_tracing_dynamic_event!(
                        target: "sqlx::query",
                        tracing_level,
                        summary,
                        db.statement = sql,
                        rows_affected = self.rows_affected,
                        rows_returned = self.rows_returned,
                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
                        ?elapsed,
                        // Search friendly - numeric
                        elapsed_secs = elapsed.as_secs_f64(),
                        // When logging to JSON, one can trigger alerts from the presence of this field.
                        slow_threshold=?self.settings.slow_statements_duration,
                        // Make sure to use "slow" in the message as that's likely
                        // what people will grep for.
                        "slow statement: execution time exceeded alert threshold"
                    );

字段释义：

summary

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

db.statement

完整 SQL。字段总是存在：summary 与原 SQL 相同时它是空串 ""，不同时是 format!("\n\n{}\n", sql)——原样 SQL 前面两个换行、后面一个换行（sqlx-core/src/logger.rs:109-122）。0.8.6 里没有任何格式化：源码里还留着被注释掉的 sqlformat::format(...) 调用，sqlformat 依赖已在 #3545（首见于 0.8.3）移除。

字段名 db.statement 沿用的是 OpenTelemetry 语义约定里的属性名——生产接 OTLP 的团队可以直接把它映射成属性。注意 OTel 语义约定后来已把 db.statement 标为 deprecated（"Replaced by db.query.text"），sqlx 0.8.6 用的仍是旧名。

rows_affected / rows_returned

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

两个细节：rows_returned 只数被逐行读出的那些，fetch_one 提前丢弃流时只会记 1；SQLite 的 rows_affected 取自 sqlite3_changes()，返回的是最近一条 DML 的改动数（sqlx-sqlite/src/statement/handle.rs:95-99 的注释也这么说），所以实测插入 2 行后紧跟一条 SELECT，这条 SELECT 的事件里也是 rows_affected=2。

elapsed / elapsed_secs

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

为什么要两个？

• ?elapsed——Duration 的 Debug 格式化、带单位、保留全部精度（实测形如 343.217µs、1.102768ms、6.46534884s）——人类看日志直接读。
• elapsed_secs——纯数字、接到 metrics pipeline 里可以直接聚合——histogram(elapsed_secs) 算 p50/p99、不需要正则解析字符串。

两个字段各服务一种消费场景。源码注释也点明了 elapsed 是为向后兼容保留的：elapsed_secs 是 0.7.4 才加的（#3004）。

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（grep -rn 'target: "sqlx' --include=*.rs 可穷举）：

• sqlx::query（sqlx-core/src/logger.rs:104-105、:126、:144）——所有查询事件（普通 + 慢查询）。
• sqlx::pool::acquire（sqlx-core/src/pool/inner.rs:303、:311）——Pool::acquire() 的耗时事件，详见 §21.23。
• sqlx::postgres::notice（sqlx-postgres/src/connection/stream.rs:178、:181、:186）——Postgres NOTICE/WARNING 消息（RAISE 触发）。
• sqlx::explain（sqlx-sqlite/src/logger.rs:359-360、:432）——SQLite 驱动做可空性推断时的 EXPLAIN 分析日志，写死在 TRACE 级别。

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

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

字符串语义：

• info —— 全局 INFO 级别。
• sqlx::query=debug —— 放行 sqlx 查询事件到 DEBUG——开发时能看见每条 SQL。
• sqlx::pool::acquire=info —— 放行连接池获取事件（要先用 PoolOptions::acquire_time_level 打开，见 §21.23）。
• sqlx::postgres::notice=info —— Postgres NOTICE（RAISE NOTICE 'foo'）按 INFO 输出。

env_logger 的配置类似：

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 自己也经历了这个转换：2020 年最早的查询日志是直接用 log 写的（提交 7bc3133f "add an optional query logger (using log)"），v0.7.0 起切到 tracing（#2185）并改成结构化字段；慢查询专用消息（#2880）是 0.7.3 加的，elapsed_secs（#3004）是 0.7.4，连接池 acquire 日志（#3073）是 0.8.0。

sqlx 作为一个被广泛依赖的底层库——不能假设用户用哪一套——所以两边都照顾到：enabled 检查问两边，发射走 tracing::event! 并靠 tracing 的 log feature 兜住 log 那一路。付出的代价：logger.rs 里多一次 enabled 检查 + 一个 feature 开关——值。

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

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

两边都照顾 符合 "不把生态割裂压给用户" 的设计哲学。

21.11 QueryLogger 在驱动里的使用

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

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

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）：

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）：

let logger = QueryLogger::new(query, conn.log_settings.clone());
// logger 存进 ExecuteIter，由 ConnectionWorker 的后台线程逐步 next()
// 执行时 self.logger.increment_rows_returned(); self.logger.increase_rows_affected(...);

统一的模式：

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

三家都复用 sqlx-core/src/logger.rs（SQLite 通过 sqlx-sqlite/src/logger.rs 里的 pub(crate) use sqlx_core::logger::* 引入）。SQLite 建连时执行 PRAGMA 也走 execute::iter（sqlx-sqlite/src/lib.rs:135），所以实测每次连接都会先出一条 summary="PRAGMA foreign_keys = ON; …" 的查询事件。

21.12 连接级 tracing 事件

除了 query 日志、sqlx 还在连接池、建连和驱动内部直接用 tracing:: 宏发事件——不走 QueryLogger、不受 LogSettings 控制。这些事件大多没写 target:，target 就是模块路径（如 sqlx_core::pool::inner、sqlx_postgres::options::pgpass）。

例子：

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

tracing::debug!(
    path = %path.display(),
    "`.pgpass` file not found",
);

注意这里分了两级：找不到密码文件只记 debug（文件本来就是可选的）， 真正打开失败（权限不对之类）才 warn（同文件 :54）——帮用户诊断 "为啥连不上 DB"，又不会让没建 .pgpass 的人每次连接都看到警告。

• describe 的可空性推断（sqlx-postgres/src/connection/describe.rs:434，全文件唯一一处 tracing::）：

tracing::debug!(
    ?stmt_id,
    num_columns = meta.columns.len(),
    "number of columns in query is too large to pull nullability for"
);

describe() 是 query!() 宏用来拿 SQL schema 的。get_nullable_for_columns 给每一列绑 3 个参数（idx / table_id / col_idx），列数 × 3 一旦超过 65535 （约 2.18 万列，Postgres 单条语句绑定参数的上限）就必定失败——sqlx 在这里 只打一条 debug 就继续往下走（:433-439 之后没有 return），随后在 PgConnection::run() 里以 "too many arguments for query" 的协议错误返回； 这条 debug 日志说明了失败的真正原因。

• advisory_lock（sqlx-postgres/src/advisory_lock.rs:348；同文件 :153 另有一处 tracing::trace!）：

tracing::warn!(
    lock = ?self.lock.key,
    "PgAdvisoryLockGuard: advisory lock was not held by the contained connection",
);

PgAdvisoryLockGuard::release_now() 发现锁根本不在这条连接上（连接被 std::mem::replace 换过、或者已经被别处释放）时 warn——说明用法出错，值得生产告警。

• Postgres NOTICE（sqlx-postgres/src/connection/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——具体级别。

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

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 日志系统的一个重要承诺——不启用时零开销。怎么做到？

开销来源：

1. QueryLogger::new(...)——栈上一个小结构体（一个 &str + 两个 u64 + 一个 Instant + 一份 LogSettings）、外加一次 Instant::now()。小但不是零。
2. increment_rows_returned / increase_rows_affected——普通 u64 += （不是原子操作，QueryLogger 是 &mut 独占的）。
3. finish() 里的判断——如果两个级别都是 LevelFilter::Off、private_level_filter_to_levels 返回 None、后续全部跳过——没有事件构造、没有格式化。
4. finish() 里 enabled 检查——log_enabled! 和 tracing::enabled! 都是被两个 crate 优化过的快速路径。

总开销——关闭日志时基本由 Instant::now() 主导，是纳秒量级；query 执行时间至少微秒（本地 DB）到毫秒（远程 DB）——完全可忽略。想要自己场景的确切数字，cargo bench 跑一次对照。

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

优化细节：

• QueryLogger 的 settings.clone()——3 个字段全是 Copy 类型（两个 LevelFilter + 一个 Duration），derive 出来的 Clone 就是一次浅拷贝——比想象中的 "clone" 便宜得多。
• Instant::now() 在 Linux 上通常走 vDSO、不真正陷入内核。
• 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）：

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

这段代码的效果：

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

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

21.16 tokio 和 tracing span 传播

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

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

sqlx 在异步路径上——每个 query 都经过多个 await 点（send query、recv response）——业务 future 被 #[instrument] 包住后，每次 poll 都会重新进入该 span——所以 logger.finish() 发 event 时、当前 span 还是业务 span——event 归属正确。

sqlx 也为此做了两处显式的传递，并非完全"自动享受"：

• try_stream! 宏（sqlx-core/src/ext/async_stream.rs:124）把流的主体包在 Instrument::in_current_span 里，流被 poll 时进入的是创建它时的当前 span。
• SQLite 的 QueryLogger 在 ConnectionWorker 的后台 OS 线程里 drop，那里本没有业务 span。worker 发命令时会把 Span::current() 一并送进通道（sqlx-sqlite/src/connection/worker.rs:373 等处）。后台线程取出命令后，先进入随命令送来的 span 再执行（同文件 :144-145）。实测 #[instrument] 的 handler{user_id=42} 会出现在 SQLite 查询事件前面，而 ThreadId 是 worker 线程的。

21.17 从开发到生产的 subscriber 配置

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

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();

日志输出样例：

下面是用 SQLite 内存库实跑的输出（为演示把慢阈值调到了 1ms；ThreadId(66) 是 SQLite worker 线程）：

2026-09-24T19:58:29.494400Z DEBUG ThreadId(66) sqlx::query: summary="SELECT * FROM users" db.statement="" rows_affected=0 rows_returned=0 elapsed=221.572µs elapsed_secs=0.000221572
2026-09-24T19:58:29.709352Z  WARN ThreadId(66) sqlx::query: slow statement: execution time exceeded alert threshold summary="WITH RECURSIVE c(x) AS …" db.statement="\n\nWITH RECURSIVE c(x) AS (SELECT 1 UNION ALL SELECT x+1 FROM c WHERE x < 100000) SELECT count(*) FROM c\n" rows_affected=0 rows_returned=1 elapsed=214.819934ms elapsed_secs=0.214819934 slow_threshold=1ms

fmt 格式器把 message 放在最前，其余字段按宏里的书写顺序排列。

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

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：

{
  "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 调级别、不用改代码。注意 from_default_env() 只在初始化时读一次环境变量，改了要重启进程；要在线调级别，得配合 tracing_subscriber::reload。

21.18 接 OpenTelemetry

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

下面是 opentelemetry-otlp 较早版本的 new_pipeline() 写法，新版本的构造 API 已改，具体以你所用版本的文档为准：

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"。注意这里直接调 set_global_default，不会像 fmt().init() 那样顺带安装 LogTracer，依赖 log 的其他库的日志要另外桥接（§21.30）。在 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_threshold=500ms

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

21.19 SQL 脱敏的现状

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

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

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。

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

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 里做处理。最粗的办法是用过滤器整条丢弃：

use tracing_subscriber::filter::FilterFn;

// FilterFn 只能看到 metadata（target、级别、字段名），看不到字段的值，
// 所以它只能决定整条事件要不要，不能只抹掉 SQL 里的某一段
let drop_sqlx_query = FilterFn::new(|metadata| metadata.target() != "sqlx::query");

想保留事件、只改写 db.statement 的值，就得在格式化阶段动手（自定义 FormatFields），或者自己写一个 Layer 读出字段、脱敏后再输出。

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

21.20 log_statements(Off) 关闭日志

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

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

或者一句话：

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

（sqlx-core/src/connection.rs:262-266）

适用场景：

• 超高 QPS 系统——每条 query 一条 log 会压垮日志系统。
• 合规严格——PII 不能进日志——直接关了最保险。
• 有其他 APM 工具——已经由别的追踪手段记录了查询、sqlx 日志重复。

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

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

21.21 log 后端的选择

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

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

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

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——混用两套时的胶水：

tracing_log::LogTracer::init()?;

这行初始化后——所有 log::info! 都被 tracing subscriber 捕获。sqlx 的查询日志本身不需要这座桥（它只发 tracing 事件），要桥接的是依赖里其他走 log 的库。另外，tracing-subscriber 默认开启 tracing-log feature，fmt().init() 已经顺带装好了 LogTracer，这时再调一次会返回错误（§21.30）。

21.22 慢查询告警的落地

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

最简单——grep 日志：

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

进阶——Prometheus alert rule：

# 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 里累积——比如自定义一个 layer：

use tracing_subscriber::Layer;
use tracing::Event;

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.metadata().fields().field("slow_threshold").is_some()
        {
            SLOW_QUERY_COUNTER.inc();
        }
    }
}

SLOW_QUERY_COUNTER 是 Prometheus Counter——每次 slow query 触发——+1——Grafana 画曲线。慢查询事件和普通事件是两个不同的 callsite，只有前者的字段集里有 slow_threshold，所以查 metadata 就够了（用 AtomicU64 代替 Counter 实测，计数正确）。

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

21.23 pool acquire 的日志

连接池获取有自己的一套事件，target 是 sqlx::pool::acquire（sqlx-core/src/pool/inner.rs:295-316）：

let acquired_after = acquire_started_at.elapsed();

let acquire_slow_level = self
    .acquire_slow_level
    .filter(|_| acquired_after > self.options.acquire_slow_threshold);

if let Some(level) = acquire_slow_level {
    private_tracing_dynamic_event!(
        target: "sqlx::pool::acquire",
        level,
        aquired_after_secs = acquired_after.as_secs_f64(),
        slow_acquire_threshold_secs = self.options.acquire_slow_threshold.as_secs_f64(),
        "acquired connection, but time to acquire exceeded slow threshold"
    );
} else if let Some(level) = self.acquire_time_level {
    private_tracing_dynamic_event!(
        target: "sqlx::pool::acquire",
        level,
        aquired_after_secs = acquired_after.as_secs_f64(),
        "acquired connection"
    );
}

三个开关都在 PoolOptions 上（sqlx-core/src/pool/options.rs:220、:227、:237），默认值在 :154-159：

选项	默认值	含义
acquire_time_level	LevelFilter::Off	每一次 acquire 的耗时事件——默认关，源码注释："Logging all acquires is opt-in"
acquire_slow_level	LevelFilter::Warn	超过阈值的 acquire 用什么级别记
acquire_slow_threshold	Duration::from_secs(2)	慢 acquire 的阈值

所以开箱即用就有慢 acquire 的 WARN 事件（池满、等待排队时会看到），而"每次 acquire 都记"要显式打开：

let pool = PgPoolOptions::new()
    .acquire_time_level(log::LevelFilter::Debug)          // 打开每次 acquire 的日志
    .acquire_slow_threshold(Duration::from_millis(500))   // 收紧慢阈值
    .acquire_slow_level(log::LevelFilter::Warn)
    .connect(database_url).await?;

一个必须知道的坑——字段名在源码里拼错了：是 aquired_after_secs（少一个 c），不是 acquired_after_secs。做 Grafana / Loki 面板时按源码里的拼写写，否则查不到数据。

注意 Pool::acquire() 仍然没有开 span——只有点事件。想知道 acquire 在业务链路里占了多久，还是靠业务侧的 span：

#[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 多数时候在池里有闲连接时直接返回——开 span 数据膨胀。真要 profile acquire 卡在哪一步——用 tokio-console。

21.24 用 tokio-console 看连接池

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

启用（tokio 要开 tracing feature，编译时带 RUSTFLAGS="--cfg tokio_unstable"）：

console_subscriber::init();

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

• 每个 task 的 busy / idle 时间、被 poll 的次数——持有连接的业务 task 长时间 busy 或长时间没被唤醒，都会显出来。
• tokio 自身资源（定时器、tokio::sync 原语）的状态。

它看不到的也要心里有数：console 展示的是 task 和 tokio 资源，不是 sqlx 的连接对象，所以不会列出"每个连接 idle / busy"；连接池的等待队列用的是 futures-intrusive 的信号量（sqlx-core/src/sync.rs），不是 tokio 的，也不会作为资源出现；SQLite 的 worker 是 OS 线程，不是 task。

sqlx 这边无需任何集成——tokio-console 从 tokio runtime 拿信号。

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

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

graph TB
    A[sqlx query!/query/query_as] --> B[driver executor]
    B --> C[QueryLogger::new]
    C --> D[wire protocol 发送]
    D --> E[wire protocol 接收]
    E --> F[解析结果]
    F --> G[logger.increment_rows_returned]
    F --> H[logger.increase_rows_affected]
    G --> I[Drop QueryLogger]
    H --> I
    I --> J[finish]
    J --> K{level == Off?}
    K -->|是| L[丢弃,零开销]
    K -->|否| M{log_enabled or tracing enabled?}
    M -->|否| L
    M -->|是| N[parse_query_summary]
    N --> O{was_slow?}
    O -->|否| P[发 普通事件]
    O -->|是| Q[发 slow 事件]
    P --> S[tracing crate]
    Q --> S
    S -->|未设置 tracing subscriber 时<br/>由 log feature 转发| R[log crate]
    R --> T[env_logger/fern]
    S -->|已设置| U[tracing_subscriber]
    T --> V[stdout/file]
    U --> V
    U --> W[OpenTelemetry Collector]
    W --> X[Jaeger/Datadog/Prometheus]

这张图说明 sqlx 日志从query 发起到可观测性后端的完整数据流。从 QueryLogger::new 到发事件的部分对应 sqlx-core/src/logger.rs，tracing → log 的转发由 tracing 自身的 log feature 完成，再往后是用户配置的 subscriber。

21.26 评估数据库客户端日志能力的检查清单

这里只讲 sqlx 侧可以从源码核实的事实，其他库的行为请以你使用的那个版本的文档 / 源码为准（它们的日志实现也在演进）。

sqlx 在 0.8.6 里开箱就有的东西：

• 查询级事件——不需要用户 wrap，任何 query / query_as / query! 都会经过 QueryLogger。
• 慢查询分级——普通查询和慢查询用不同的级别（默认 Debug vs Warn），阈值可配。
• 结构化字段——summary / db.statement / rows_affected / rows_returned / elapsed / elapsed_secs / slow_threshold，不是一条格式化好的字符串。
• log 和 tracing 两个生态都能收到（§21.10、§21.30）。
• 连接池 acquire 也有独立 target（§21.23）。

评估其他客户端库时，可以拿这五条当检查清单——"有没有查询级事件、有没有慢查询分级、字段是不是结构化、支不支持你在用的日志生态、连接池有没有观测点"。

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

"sqlx::query" 是一个写死在源码里的字符串字面量（sqlx-core/src/logger.rs:104、:126、:144），不是 module_path!() 的自动值——这本身就是"把 target 名当公共 API"的信号。文档里并没有成文的稳定性承诺，但从历史看它确实没变过：v0.9.0 的 logger.rs 里 target 仍是 "sqlx::query"。

这个约定隐含：

• 用户配置 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 上生产

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

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

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

误用 2：slow threshold 设得过小

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

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

正确——threshold 应该按业务实测的延迟分布来定，放在正常查询的高分位（比如 p99）之上，让它只抓异常值。

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

sqlx 日志发出来了、但没人消费——sqlx 发的事件到 tracing 全局 subscriber、如果既没初始化 subscriber、也没装 log 后端，事件就无处可去——日志丢失。

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

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

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

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：

#[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——日志层级清晰。

事务控制语句是否计入各驱动不同：MySQL 的 BEGIN、COMMIT 都经 execute 发出（sqlx-mysql/src/transaction.rs:32、:47），会各多一条；Postgres 的 COMMIT 经 execute（sqlx-postgres/src/transaction.rs:48）会记，BEGIN 走 queue_simple_query（:33）不记；SQLite 的 worker 直接 handle.exec(...) 开启和提交事务（sqlx-sqlite/src/connection/worker.rs:228、:259），不经过 QueryLogger。

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

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

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 迭代器、由 ConnectionWorker 的后台线程逐个 .next() 推进（sqlx-sqlite/src/connection/worker.rs:167 起）——logger 必须和迭代器生命周期一致。

实现——logger 作为 struct 字段——struct drop 时 logger drop——RAII 语义仍然满足——即使 worker 因为出错或达到 limit（fetch_one / fetch_optional）提前 break / drop(iter)，也会正确发日志。

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

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

21.30 tracing-log 桥接的时序细节

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

要分两种初始化方式看：

1. tracing_subscriber::fmt().init()（或 registry().with(...).init()）：tracing-subscriber 默认开启 tracing-log feature，init() / try_init() 在设置全局 subscriber 之后会顺带安装 LogTracer。此后所有 log::info!("msg") 都被转换成 tracing 事件发到 subscriber。这时再手动调一次 tracing_log::LogTracer::init() 反而会失败，实测返回 Err("attempted to set a logger after the logging system was already initialized")。
2. 直接 tracing::subscriber::set_global_default(subscriber)（§21.18 的 OTLP 写法），或关掉了 tracing-subscriber 的默认 feature：这时不会自动装 LogTracer，需要自己调 tracing_log::LogTracer::init()。

坑：第 2 种情况下忘了装桥——log crate 的 global logger 是 no-op——任何走 log crate 的事件都丢了。sqlx 的查询日志本身不走这条路（下文会讲），但依赖里走 log 的库不少，sqlx 自己也有几处直接 log::warn!（如 sqlx-mysql/src/connection/establish.rs:60 的明文密码警告、sqlx-core/src/net/tls/tls_rustls.rs:225）。用户可能以为 tracing subscriber 会自动接住 log 的调用——这种初始化方式下不会。

sqlx 的查询日志不受这个坑影响——它在发射前同时问 log 和 tracing 两边「这个级别要不要收」、任一答「要」就发——即使用户只装了其中一套，查询日志也不会被静默吞掉。双轨 enabled 判断是对用户的保护。

反面——两边的 enabled 都问过了，会不会最后发出两份、重复打印？

不会——因为 sqlx 在 finish() 里只发一次事件：private_tracing_dynamic_event! 展开的是 tracing::event!，而 sqlx-core/Cargo.toml:78 把 tracing 的依赖写成 tracing = { version = "0.1.37", features = ["log"] } —— tracing 的 log feature 会让每个 tracing 事件在没有 tracing subscriber 时额外发一条 log 记录。换句话说：

• sqlx-core/src/logger.rs:104 的 log::log_enabled! 只用来做 enabled 判断，查询日志路径上 sqlx 从不调用 log::log! 发事件。
• 唯一的发射点是 tracing::event!，log 那一路由 tracing 的 log feature 代劳。

所以装不装 tracing-log，用户 subscriber 都只会收到一份。tracing 的 log feature 在宏里用 dispatcher::has_been_set() 判断：一旦设置过 tracing 全局 subscriber，就不再往 log 发。实测只装 env_logger（RUST_LOG=debug）时，sqlx::query 事件照样以 log 记录输出；用 fmt().init() 时每条查询也只出现一次。

这个细节能看出 sqlx 团队对跨生态的细致把控。

21.31 Postgres NOTICE 特殊路径

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

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

级别映射（sqlx-postgres/src/connection/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()。

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

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: batch size 2000 too large

（字段名恰好叫 message，fmt 格式器会把它当正文输出、不带 message= 前缀。这一行是用同样的 target / level / 字段在本地模拟得到的，未连 Postgres 实跑。）

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

21.32 结构化字段 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 是结构化日志的典范——每个字段独立：

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 直接做数值运算。注意 fmt().json() 默认把事件字段放在嵌套的 fields 对象里，Loki 的 | json 用 _ 展平后字段名是 fields_elapsed_secs；下面的查询假设配置时加了 .flatten_event(true)，把字段提到顶层：

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

这个 LogQL 查询——"过去 5 分钟里、耗时超过 0.5 秒的查询每秒多少条"——sqlx 的结构化日志直接支持（target 是 JSON 里的字段，要在 | json 之后过滤，不能写进流选择器）。

结论——sqlx 并不是一开始就结构化的：早期查询日志用 log 拼字符串，v0.7.0 切到 tracing 后才改成独立字段（§21.10）。它现在的字段设计，是这次迁移的结果。

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

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

具体：

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

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

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

强绑定后端、强推聚合策略的库，会把自己的选择强加给所有用户。

sqlx 守住了这条边界——sqlx-core/src/logger.rs 全文 173 行，就给出了生产上够用的查询事件。

推广到 Rust 生态——tokio 等底层库也是类似思路——产出 tracing 事件（tokio 需开 tracing feature）、不绑定聚合后端——用户拼装。

21.34 一个典型场景：用 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、查：

sum by (db_statement) (count_over_time({app="api"} | json | target="sqlx::query" [5m]))

（JSON 日志里的键是 db.statement。Loki 的 json 解析器会按 Prometheus 标签命名规则清洗提取出的键名，点号不合法，字段名变成 db_statement；这里同样假设开了 .flatten_event(true)，否则字段嵌在 fields 里，名字是 fields_db_statement。该字段的值前后带换行，SQL 短到只有几个词时是空串，§22.15 有处理办法。）

结果：

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：

let orders_with_items = sqlx::query!(
    r#"SELECT o.id, o.created_at,
              array_remove(array_agg(oi.id), NULL) AS "item_ids!: Vec<i64>"
       FROM orders o
       LEFT JOIN order_items oi ON o.id = oi.order_id
       WHERE o.user_id = $1
       GROUP BY o.id, o.created_at
       ORDER BY o.created_at DESC"#,
    user_id
).fetch_all(&pool).await?;

不能图省事写 array_agg(oi.*) 聚整行：聚出来的是行类型（复合类型）数组，query! 家族没有内置映射，编译期就报 "no built in mapping found"（§22.15）。聚具体的列，再按 id 取明细或在应用层组装。（Postgres 专有写法，本机未实跑。）

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

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

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

21.35 从三支柱回看 sqlx 可观测

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

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

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

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

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

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

21.36 延伸思考题

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

1. 为什么 QueryLogger 没持有 &Connection？

   答：解耦。logger 只关心 SQL + 耗时 + 计数——不需要知道是哪条连接。将来连接换实现（比如 QUIC 替换 TCP）—— logger 不受影响。单一职责——logger 的职责就是记录查询元数据、不是管理连接。

2. 为什么把 LogSettings clone 进 logger 而不是借用？

   答：生命周期解耦。借用会让 logger 和 connection 的生命周期绑定——复杂。LogSettings 在 64 位平台上是 32 字节（两个各 8 字节的 LevelFilter + 16 字节的 Duration，size_of 实测），clone 就是一次按位拷贝——开销可忽略、可读性大幅提升。

3. 为什么慢查询消息里硬编码 slow 这个词？

   答：运维肌肉记忆。Linux sysadmin 遇到性能问题第一反应是 grep slow——sqlx 对齐这个 convention——减少用户学习成本、融入既有工作流。

4. 为什么用 target = "sqlx::query" 而不是 module_path!() 的自动值？

   答：稳定性。模块路径随重构变——sqlx_core::logger 和 sqlx_core::query::logger 可能变——手动固定 target 让用户配置跨版本稳定——target 是 API 的一部分。

5. sqlx 为什么没实现 #[instrument] 风格的 query span？

   答：性能。query span 会给每次 query 开一个 span——高 QPS 服务 span 数据爆炸——违反 "观测不应拖性能" 原则。用event 而不是 span 是正确选择——span 由用户业务层控制粒度。

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

21.37 本章小结与下章预告

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

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

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

21.38 和《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 的官方姿势。
• 该专栏 §17.4 讲 tokio-console —— 本章 §21.24 提到的 console_subscriber::init() 背后的 runtime 可观测机制——和 sqlx 无关但免费享受。

对照：

• 本章 §21.15 "tracing span 的生命周期与 sqlx"↔《Tokio 源码深度解析》专栏第 17 章 §17.3 的两层模型——两个专栏从不同角度讲同一件事。
• 本章 §21.24 "用 tokio-console 看连接池"↔《Tokio 源码深度解析》专栏第 17 章 §17.4 的 tokio-console 工具——sqlx 不做任何集成、直接受益。
• 本章 §21.18 接 OpenTelemetry ↔《Tokio 源码深度解析》专栏第 17 章 §17.2 把 Metrics 连到 Prometheus——都是把观测数据导出到外部系统，只是 Tokio 那边用 prometheus crate 直接采样 RuntimeMetrics，不经过 tracing。

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