## 01｜别再只会 `print` 了：Python 可观测性从日志到链路追踪

萤火阳光

232人浏览 · 2026-03-11 17:15:32

萤火阳光 · 2026-03-11 17:15:32 发布

01｜别再只会 `print` 了：Python 可观测性从日志到链路追踪

文章目录

摘要

服务一慢，群里第一句话通常是“先看看日志”。但很多项目只有零散 print，真正排障时很难还原现场。
这篇文章从一线排障场景出发，整理一套能快速落地的最小方案：结构化日志、trace_id 贯穿、函数耗时埋点。
重点不是“日志变多”，而是让每一次故障都能定位到具体链路和耗时节点。

SEO 摘要

围绕 Python 服务可观测性建设，给出结构化日志、trace_id 链路追踪和耗时埋点的实践方案。适合后端工程师用于慢请求定位、故障复盘和值班排障提效。

问题背景

典型低效日志长这样：

request failed
db timeout
unknown error

它们都缺少上下文：是谁触发、哪条请求、耗时多少、失败在哪一层。

设计目标

每条日志可机读（JSON）。
一次请求有唯一 trace_id。
关键函数自动记录耗时。

代码实现

import json
import logging
import time
import uuid
from contextvars import ContextVar
from functools import wraps
from typing import Any, Callable

logging.basicConfig(level=logging.INFO, format="%(message)s")
trace_id_ctx: ContextVar[str] = ContextVar("trace_id", default="-")

def set_trace_id() -> str:
    tid = uuid.uuid4().hex[:16]
    trace_id_ctx.set(tid)
    return tid

def get_trace_id() -> str:
    return trace_id_ctx.get()

def log_event(event: str, **kwargs: Any) -> None:
    payload = {
        "ts": round(time.time(), 3),
        "event": event,
        "trace_id": get_trace_id(),
        **kwargs,
    }
    logging.info(json.dumps(payload, ensure_ascii=False))

def measure_cost(func: Callable[..., Any]) -> Callable[..., Any]:
    @wraps(func)
    def wrapper(*args: Any, **kwargs: Any) -> Any:
        start = time.perf_counter()
        try:
            return func(*args, **kwargs)
        finally:
            log_event("function_cost", func=func.__name__, cost_ms=round((time.perf_counter() - start) * 1000, 2))
    return wrapper

@measure_cost
def query_user(uid: int) -> dict[str, Any]:
    time.sleep(0.03)
    return {"uid": uid, "name": "alice"}

def handle_request(uid: int) -> dict[str, Any]:
    set_trace_id()
    log_event("request_start", uid=uid)
    data = query_user(uid)
    log_event("request_end", uid=uid, ok=True)
    return data

验证方式

连续压测 100 次请求，抽样检查日志是否完整包含：trace_id / event / cost_ms。
随机注入异常，确认能够按 trace_id 还原整条调用链。

常见坑

只打错误日志，不打成功路径，导致链路断裂。
日志里打印敏感信息（手机号、token）未脱敏。
只有平均耗时，没有 P95/P99 指标。

指标对比示例

指标	改造前	改造后	结论
故障平均定位时长	45 分钟	12 分钟	排障效率显著提升
慢请求可追踪率	38%	91%	链路可见性增强
日志可检索字段覆盖率	30%	95%	机读分析能力提升

结尾互动问题

你的服务目前是否已经做到按 trace_id 还原完整链路？
你们团队线上最常见的是慢查询还是第三方超时？
如果只做一项改造，你会先做结构化日志还是耗时埋点？

可观测性架构图

深度重构：从“有日志”到“可运营日志”

很多团队已经“有日志”，但仍然排障慢，原因在于日志没有完成从开发视角到运营视角的转化。开发视角更关注“代码到没到这里”，运营视角更关注“影响多少用户、持续多久、是否自动恢复、是否需要升级处理级别”。因此，结构化日志只是起点，真正的可观测性还需要日志分级、事件语义统一、指标联动和告警闭环。

第一步是统一事件语义。比如登录流程，不要混用 login_start、user_login_begin、auth_begin 三种命名，否则后续统计会非常混乱。建议每个业务域维护一个事件命名规范文档，规定事件名、字段名、字段类型和必填项。这样做的价值在于：即便团队成员变动，日志资产仍然可以长期复用，不会因“写日志风格变化”导致平台分析失效。

第二步是建立日志等级策略。INFO 记录关键业务路径，WARN 记录可恢复异常，ERROR 记录影响用户或核心链路的失败。不要把所有异常都打 ERROR，否则告警系统会噪声过高，真正的故障被淹没。很多团队后期引入了“错误预算”机制，本质上也是基于分级日志和 SLO 指标做治理。

第三步是把日志与指标绑定。单独看日志你知道“发生了什么”，单独看指标你知道“问题多严重”。两者结合，才能形成“发现 -> 定位 -> 修复 -> 验证”的完整闭环。比如当 request_error_rate 超过阈值时，自动跳转到对应 trace_id 集合；当 P95 抖动时，自动展示耗时 TopN 函数，排障路径会短很多。

第四步是数据治理与成本控制。日志不是越多越好，字段冗余会造成存储成本飙升。建议按“在线检索期 + 归档期”管理日志生命周期，核心业务保留更长，低价值调试日志缩短存储周期。同时对大字段做截断和脱敏，避免日志平台成为新的风险源。

生产落地方法：一周可执行路线图

Day 1：统一 trace_id 注入方式，确保入口层必带请求标识。
Day 2：梳理 10 个核心业务事件，定义字段规范。
Day 3：补齐关键函数耗时埋点，覆盖 DB、缓存、外部 RPC。
Day 4：接入最小告警规则（错误率、延迟、超时）。
Day 5：做一次故障演练，验证日志能否支持 10 分钟内定位。
Day 6：评估日志字段冗余与存储成本，执行瘦身。
Day 7：复盘并输出团队级规范文档。

常见误区再补充（进阶版）

一是“只关注技术栈，不关注流程”。很多团队买了观测平台，却没有值班响应机制，导致告警无人处理。二是“只做工具接入，不做业务语义设计”，结果平台里有大量数据却无法回答管理问题。三是“缺少复盘机制”，同类故障反复发生。可观测性是工程体系，不是单一工具。

案例复盘：一次慢请求排障的完整过程

某次活动开始 20 分钟后，用户反馈“页面偶发超时”。监控上看整体 QPS 正常，但 P95 从 180ms 抬升到 900ms。值班同学先按 trace_id 抽样 30 条慢请求，发现大部分卡在同一外部接口。继续看函数耗时日志，query_profile 平均耗时从 80ms 升到 600ms，同时 retry_count 增加。再结合业务日志确认，外部接口在高峰期限速导致大量重试，最终拖慢整条链路。

处理动作分三步。第一步，给外部接口增加熔断和本地缓存兜底，先把用户请求稳定住。第二步，补充 upstream_timeout、retry_attempt 两个字段，便于后续统计真实影响范围。第三步，把对应事件加入告警规则：当 5 分钟内超时率超过阈值时自动通知值班群。处理后 15 分钟内 P95 恢复到 260ms，活动期间未再出现大面积超时。

这次复盘的关键结论是：不是没有日志，而是之前日志无法支撑“从症状到根因”的快速收敛。把日志字段标准化后，排障链路变成“看指标 -> 抽样链路 -> 定位函数 -> 触发处置”，效率明显提升。