我印象很深的一次排障是某订单系统上线之后偶发页面加载卡顿。当时几个同事的第一反应就是加日志但惯用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, maxBytes10 * 1024 * 1024, backupCount5, encodingutf-8, ) file_handler.setLevel(logging.INFO) file_handler.setFormatter(formatter) logger.addHandler(console) logger.addHandler(file_handler) return logger这里maxBytes10 * 1024 * 1024的意思是单个日志文件最大 10MB超过后自动轮转。backupCount5表示最多保留 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, useru001, amount99.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_asciiFalse)使用它的方式和普通 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.123Zlevel日志级别INFO / ERROR / WARNINGlogger出处模块order_serviceservice服务名order-apitrace_id链路 IDa1b2c3d4e5f6...message人类可读描述create order successduration_ms耗时120.5user_id用户标识示例u001error_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(endpointhttp://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 resultstart_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 常用的反查路径实际排查时这套联动用起来是这样在链路追踪平台找到那条慢请求复制 Trace ID。到日志平台按trace_id精确检索一瞬间拉出该请求在全部服务里留下的日志。按时间线梳理先看哪个 Span 耗时异常再找对应的日志级别。如果需要继续从日志中的业务字段比如订单号再横向扩散查询。这套流程熟练之后定位一条跨服务问题的速度比我当年用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 注入日志。做完这两件事再回头看线上问题你会觉得手里终于有了地图。