告别print：Python可观测性之结构化日志与链路追踪

我印象很深的一次排障，是某订单系统上线之后偶发页面加载卡顿。当时几个同事的第一反应就是加日志，但惯用print的同事直接在业务代码里打了十几行中间的变量，跑到终端一看，刷屏倒是快，可一关窗口什么都没有，更别说按请求去查上下文。最后是拿着一次慢请求的 Trace ID 顺着日志逐行回溯，才定位到某个公共缓存把 key 打到了同一分片，导致热点请求互相等待。从那之后我对 Python 可观测性彻底改观——日志、指标、链路追踪，这三件事平时看着不起眼，真到出问题的时候，一件都不能少。

这篇就来写写，从最基础的“别再只会 print”，到结构化日志，再到链路追踪，这条路具体怎么走，每一步解决了什么问题，又有哪些坑是实操里躲不掉的。

1. 可观测性到底是什么，为什么 print 救不了你

1.1 print 的三个硬伤

我见过不少写了三五年 Python 的开发者，本地调试全靠print，生产环境出问题就临时在代码里加print，然后盯着容器标准输出看。这样不是不行，但离“可观测性”差了十万八千里。

第一个硬伤是没有级别控制。print是二进制开关，要么全打要么全不打。你不可能让它在本地打印 DEBUG 细节，到生产只打印 ERROR，更不可能通过环境变量随时调级别。第二个硬伤是缺少结构化上下文。print输出一坨字符串，没有时间戳、没有服务名、没有进程编号、没有请求 ID，出了问题你根本不知道这条输出来自哪台机器、哪个分支、哪次请求。第三个硬伤是没有可靠的输出通道。标准输出一断、容器一重启，日志就没了；文件要不要切割、要不要按天存档、磁盘满了怎么处理，这些问题print完全不管。

提示：print不是不能用，而是只能用于临时脚本。凡是需要留存、检索、告警的日志，都必须走专业日志组件。

1.2 日志、指标、链路追踪，谁也不能替谁

可观测性通常被拆成三个支柱：日志（Logs）、指标（Metrics）、链路追踪（Traces）。它们的定位完全不同。

日志描述的是“某台机器上某个时刻发生了什么”，粒度最细，但彼此之间是割裂的。指标描述的是“系统现在的健康状况”，比如 QPS、延迟、错误率、内存占用，适合做告警和趋势观察，但回答不了“这一次请求为什么慢”。链路追踪描述的是“一条请求在整个系统里的完整路径”，它能告诉你在服务和数据库之间反复横跳的这 100ms 到底耗在哪里。

这三者不是替代关系。链路能帮你缩小范围，日志能帮你确认根因，指标能帮你判断影响面。我后来养成的排查习惯是：先从指标看异常，再用 Trace ID 找链路，最后顺着链路里打点过的日志字段落到根因。这才是可观测性真正起作用的方式。

2. 从 print 到 logging：先把日志基础打好

2.1 logging 模块的四个核心对象

Python 标准库的logging模块，设计上很像一套日志加工流水线，里面有四个角色需要分清。

• Logger：日志的入口，你代码里调用logger.info()的就是它。
• Handler：决定日志去哪，比如输出到控制台、写入文件、发送到远程。
• Formatter：决定日志长什么样，比如时间格式、是否带模块名。
• Filter：决定日志输出前的过滤和加工，比如给日志附加上下文。

很多人第一次用logging就踩坑，是因为直接把logging.info()当全局函数用。这样用虽然能跑，但无法区分模块、无法灵活配置不同组件的级别。规范做法是每个模块里都通过logging.getLogger(__name__)获取自己的 logger，然后由入口统一配置 handler。

2.2 一套可以直接抄的日志配置

下面这套配置，是我平时新项目起步就会用的基础版本。既有控制台输出方便本地开发，又有滚动文件输出方便生产留存。

import logging import sys from logging.handlers import RotatingFileHandler def setup_logger(name: str = "app") -> logging.Logger: logger = logging.getLogger(name) logger.setLevel(logging.DEBUG) fmt = "%(asctime)s | %(levelname)s | %(name)s | %(message)s" formatter = logging.Formatter(fmt) console = logging.StreamHandler(sys.stdout) console.setLevel(logging.DEBUG) console.setFormatter(formatter) # 单文件最大 10MB，保留 5 份备份 file_handler = RotatingFileHandler( "app.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8", ) file_handler.setLevel(logging.INFO) file_handler.setFormatter(formatter) logger.addHandler(console) logger.addHandler(file_handler) return logger

这里maxBytes=10 * 1024 * 1024的意思是单个日志文件最大 10MB，超过后自动轮转。backupCount=5表示最多保留 5 个旧文件。也就是说，这套配置最坏情况下会占用约 60MB 磁盘空间。计算方式是maxBytes * (backupCount + 1)，其中的 +1 是当前正在写的文件。在实际生产里，磁盘占用不根据这个量级，建议把maxBytes调大到几百 MB，再让采集组件定期拉走。

2.3 日志级别与生产环境的取舍

日志级别从低到高是 DEBUG、INFO、WARNING、ERROR、CRITICAL。我的推荐很直接：本地开发用 DEBUG，测试环境用 INFO，生产环境默认 INFO，但在关键模块上可以对某个 logger 单独调到 DEBUG。

生产环境不建议全局开 DEBUG 还有一个原因：性能。日志输出本身是 I/O 操作，级别越低输出越多，对吞吐的影响就越明显。尤其是 Python 这种解释型语言，格式化大量日志字符串同样消耗 CPU。所以生产上日志级别宁可设高一点，也不要为了“多留点信息”全量 DEBUG，否则请求量稍大，日志先成为瓶颈。

3. 结构化日志：让日志从“人能看”变“机器能查”

3.1 文本日志的问题在于没法查

传统文本日志长这样：

2025-01-10 14:00:01 | INFO | order_service | create order success, user=u001, amount=99.5

人眼扫着还行，可真要检索就有麻烦了。想查某用户的所有操作，得靠正则从字符串里截取；想统计某接口的平均耗时，还得先解析日志格式。更难受的是，一旦日志里混入异常堆栈、特殊字符、换行符，正则解析很容易被带偏。

结构化日志要解决的就是这件事：把日志变成 JSON 这样的键值对格式。每条日志都是一条独立的、机器可解析的记录，字段含义明确，后续接入日志平台、告警规则、排查链路都要方便得多。

3.2 徒手实现一个 JsonFormatter

不引入任何第三方库，只靠标准库也能写出 JSON 格式的 Formatter。思路是重写format方法，把日志所有需要的信息塞到一个字典里，再json.dumps出来。

import json import logging class JsonFormatter(logging.Formatter): def format(self, record): base = { "ts": self.formatTime(record, self.datefmt), "level": record.levelname, "logger": record.name, "message": record.getMessage(), } if record.exc_info: base["exc_info"] = self.formatException(record.exc_info) for key, value in record.__dict__.items(): if not key.startswith("_") and key not in base: base[key] = value return json.dumps(base, ensure_ascii=False)

使用它的方式和普通 Formatter 没有区别：

handler.setFormatter(JsonFormatter()) logger.info("order created", extra={"order_id": "A10086", "amount": 99.5})

extra参数是标准库本身就支持的，凡是传进去的字段都会出现在record.__dict__里，上面的 Formatter 会自动把它们合并进 JSON 输出。这样输出中的每条日志就都带上业务字段了。

注意：extra传入的字段名不要和内置属性冲突，比如别覆盖message、levelname。这会带来不可预期的问题。如果项目里没有规范，约定统一用驼峰或下划线风格，别混着用。

3.3 推荐字段清单

结构设计上，我建议每条日志至少包含这么几类信息：

字段	含义	示例
ts	精确到毫秒的时间戳	2025-01-10T14:00:01.123Z
level	日志级别	INFO / ERROR / WARNING
logger	出处模块	order_service
service	服务名	order-api
trace_id	链路 ID	a1b2c3d4e5f6...
message	人类可读描述	create order success
duration_ms	耗时	120.5
user_id	用户标识（示例）	u001
error_type	错误类型	TimeoutError

前四五个字段是基础设施，后面的是业务字段。设计原则是：每多一个字段，就多一种检索维度，但也多一份输出成本。不要一股脑把整个请求参数全塞进日志，那样日志量会大到你根本不想看。

4. 链路追踪的完整实操：用 OpenTelemetry 把请求串起来

4.1 Trace 和 Span：先理解这两个概念

链路追踪里的核心模型是 Trace 和 Span。

一条从客户端发起的完整请求链，从网关到服务 A，再到服务 B 和数据库，整体是一条 Trace。Trace 里的每一步，比如“服务 B 处理订单”“访问缓存”“调用外部接口”，都是一个 Span。Span 有开始时间、结束时间、父级关系、属性和事件。多个 Span 拼在一棵树上，就是一条 Trace。

想象一下做饭的过程：洗菜、切菜、炒菜、装盘，每一件事都是一个 Span，这整套流程合起来就是一条 Trace。如果几道菜在同一个时间段里由不同的人并行做，那就出现了多条并发子链路。分布式系统的调用关系，本质上也是这样一张树状结构。

4.2 安装与初始化

实操环节，我用的方案是 OpenTelemetry。它提供统一的标准、SDK 和运行时用的探针，下面安装几个核心库就够了。

pip install opentelemetry-sdk pip install opentelemetry-exporter-otlp pip install opentelemetry-instrumentation-flask # 如果用 FastAPI，则换成 opentelemetry-instrumentation-fastapi

初始化部分也很直白。核心思路是创建 TracerProvider，再挂上 BatchSpanProcessor，把 Span 批量发送到后端。

from opentelemetry import trace from opentelemetry.sdk.trace import TracerProvider from opentelemetry.sdk.trace.export import BatchSpanProcessor from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter provider = TracerProvider() provider.add_span_processor( BatchSpanProcessor( OTLPSpanExporter(endpoint="http://localhost:4317") ) ) trace.set_tracer_provider(provider)

用BatchSpanProcessor而不是同步逐个发送，是为了避免导出操作阻塞业务线程。它会先把 Span 缓存在内存队列里，再批量发给后端，这是生产环境默认推荐的方式。

接着对 Web 框架做自动埋点。以 Flask 为例：

from flask import Flask from opentelemetry.instrumentation.flask import FlaskInstrumentor app = Flask(__name__) FlaskInstrumentor().instrument_app(app)

只要加这一行，之后每个收到的请求都会自动生成一个 Span，记录 HTTP 方法、URL、状态码、耗时这些基础信息。这个效果是print完全给不了的。

4.3 在业务代码里手动埋点

自动埋点只能覆盖框架层面，真正的业务逻辑还得自己埋。做法是拿到 Tracer，然后用start_as_current_span包住关键业务段。

from opentelemetry import trace tracer = trace.get_tracer("order.service") def process_payment(order_id: str): with tracer.start_as_current_span("process_payment") as span: span.set_attribute("order.id", order_id) # 模拟支付处理过程 result = do_payment(order_id) span.set_attribute("payment.result", result) return result

start_as_current_span会自动把新 Span 挂到当前 Trace 链上，形成一个子 Span。子 Span 里还可以继续嵌套子 Span。你在里面设置的属性会跟随 Span 一起上报，方便后续分析。

埋点也不是越细越好。我的经验是只给三类地方埋：外部 HTTP 调用、数据库访问、核心业务动作。太细的埋点会让链路树变得极其冗长，排查时反而看不清主流程。

4.4 链路数据后端怎么选

数据采集完了，还得有地方存储和展示。开源链路追踪系统常见的有 Jaeger、Zipkin 这类，都可以直接通过 OTLP 协议接入，也可以选用支持 OTLP 接入的云端可观测平台。选型的核心标准有三点：

• 是否兼容 OTLP，兼容的话接入成本最低。
• 是否支持按 Trace ID 检索和按 Span 属性过滤。
• 是否支持采样率的动态配置。

如果只是测试学习，本地起一个轻量的链路后端，把 endpoint 指到本地端口即可。生产环境更需要关心的是存储容量和查询性能，毕竟链路数据和日志一样，都是持续增长的。

5. 把日志和链路串起来：Trace ID 联动方案

5.1 用日志过滤器把 trace_id 写进每一条日志

链路追踪接上之后，日志也不能“孤立”存在。最关键的串联动作，就是把当前 Span 的 Trace ID 放进日志字段。这样从链路平台看到一条 Trace，点进日志平台搜索对应 Trace ID，就能看到这条请求所有相关的日志。

实现方式是写一个logging.Filter，在每条日志经过时自动读取当前 Span 的上下文：

import logging from opentelemetry import trace class TraceIdFilter(logging.Filter): def filter(self, record): span = trace.get_current_span() span_context = span.get_span_context() if span else None if span_context and span_context.is_valid: record.trace_id = format(span_context.trace_id, "032x") record.span_id = format(span_context.span_id, "016x") else: record.trace_id = "0" * 32 record.span_id = "0" * 16 return True

然后把它加到 handler 上：

for handler in logger.handlers: handler.addFilter(TraceIdFilter())

由于前面我们把结构日志 Formatter 设计成会把record.__dict__里的字段打印到 JSON 里，所以trace_id、span_id会自然出现在每条日志中。这样日志就从“能看”升级成了“能串链”。

5.2 常用的反查路径

实际排查时，这套联动用起来是这样：

1. 在链路追踪平台找到那条慢请求，复制 Trace ID。
2. 到日志平台按trace_id精确检索，一瞬间拉出该请求在全部服务里留下的日志。
3. 按时间线梳理，先看哪个 Span 耗时异常，再找对应的日志级别。
4. 如果需要，继续从日志中的业务字段（比如订单号）再横向扩散查询。

这套流程熟练之后，定位一条跨服务问题的速度，比我当年用print时快了一个数量级。以前是到处问“谁改了什么”，现在是拿着 ID 直接翻证词。

6. 排查实录：这五个坑我大概率会踩

6.1 日志重复输出

很多开发者在多个模块里调用logging.basicConfig，或者在函数里重复addHandler，日志就被打印两次甚至多次。原因是每个 logger 默认会向上传播到 root logger，而 root logger 也挂了同一个 handler。解决办法是尽量在入口只配置一次 logger，并且在给某个非 root logger 加了 handler 时，设置logger.propagate = False。

6.2 异步任务拿不到 Trace ID

在线程或异步任务里做链路追踪会有上下文传播问题。普通同步调用时，OpenTelemetry 的上下文会自动跟随调用链；但一旦进了 Celery 任务或单独asyncio.create_task，当前 Span 的上下文可能就丢了。解决思路是显式地把 Trace ID、Span ID 作为任务参数传下去，或者用链路 SDK 提供的上下文传播工具，在提交任务前手动关联父 Span。不要指望它自动帮你把上下文跨进程处理好。

6.3 链路数据“断头”

链路显示到某个服务就断了，后面服务的数据没上来。这种情况多半是该服务没有初始化 OpenTelemetry，或者没有接入对应的 Web 框架探针。还有一种是调用第三方 SDK 时没有手动埋点，导致中间环节缺失。排查时先点开断掉的那个 Span，看是“没有产生子 Span”还是“子 Span 被采掉”。

6.4 日志落盘导致磁盘打满

日志是隐形的磁盘杀手。如果接入的日志组件没有轮转策略，或者轮转掉的旧日志没人清理，线上跑三天磁盘就报警。这里我给一个经验值：先算单条日志平均大小，再乘以单日请求量和平均每条请求日志条数，就能估算出单日日志体积。然后据此设置合理的maxBytes和backupCount。监控里也要加上日志文件大小的指标，别等磁盘满了才反应。

6.5 采样率该调多少

链路追踪全量采集在低流量下没问题，高流量下成本很高。生产环境往往要做采样。采样不是简单地随机丢，推荐采用“固定比例的尾部采样”或“错误必采 + 部分正常采样”。错误和慢请求必须全量记录，正常请求按比例采样即可。这样既能保留关键问题数据，又能控制存储成本。采样策略直接影响排查能力，不要拍脑袋设个 1% 就不管。

我个人体会最深的，不是某个工具多好用，而是“先有维度，再有数据”。可观测性不是把日志打得多一点，而是让日志、指标、链路具有统一的关键字段。当一条请求在所有服务里都能用同一个 Trace ID 串起来时，系统对你的可见程度会完全不同。如果你现在还在用print做线上排查，不妨按这篇的思路先迈出两步：第一步把所有日志切到结构化输出，第二步接上链路追踪并把 Trace ID 注入日志。做完这两件事，再回头看线上问题，你会觉得手里终于有了地图。