分类:后端架构 · 标签:可观测性 后端 性能优化 架构设计
适用读者:已经有一堆日志、但每次排障仍然靠猜的后端工程师;准备给服务接 Prometheus 与 OpenTelemetry,却不确定先做哪一步的负责人 结论先行:日志记录事件,指标记录趋势,追踪记录单次请求的路径。三者不是替代关系。指标告诉你「有多糟、多常见」,追踪告诉你「糟在哪一段」,日志告诉你「那一段里发生了什么」。只有平均值没有分位数,你会低估长尾;只有分位数没有 exemplar,你知道 P99 高却不知道是哪一条请求;只有 trace 没有日志,你知道哪一段慢却不知道它带了什么参数。 阅读时间:约 30 分钟 | 难度:中级到高级 | 收获:四种指标类型的取舍、P95/P99 的算法含义与样本量下限、label 基数的估算公式、W3C traceparent 的字节结构、head/tail 采样的盲区算法,以及一套能落地的 Python 埋点方式目录
/api/articles/feed,平时 P50 大约 60 毫秒,P99 大约 120 毫秒。某天下午开始,P99 爬到 400 毫秒以上,P50 只从 60 涨到 68。错误率没有变化,5xx 仍然是零。用户投诉开始出现,说"有时候要等一下才出来"。
值班的人打开日志。每条请求一行:方法、路径、状态码 200、总耗时 68 毫秒、用户 ID。翻了几百行,全是 200,耗时都在 70 毫秒上下。于是有人说"日志看着挺正常,可能是客户端网络问题"。
第二个人去看指标,指标里只有一个 http_request_duration_seconds 的平均值,画出来是一条几乎平的线,从 60 毫秒微涨到 68 毫秒。他得出"服务没变慢"。
第三个人怀疑数据库,去翻慢查询日志,阈值设的是 200 毫秒,一条都没有。
三个人都看了数据,三个人都得出了错的结论。因为三个人手上的工具都只能回答它们各自能回答的那一个问题,而这个问题不是"慢在哪一段"。
| 维度 | 日志 | 指标 | 追踪 |
|---|---|---|---|
| 记录单位 | 一条离散事件 | 一个预聚合的数值时间序列 | 一次请求的一棵 span 树 |
| 回答的问题 | 发生了什么,带了什么参数 | 多慢、多常见、趋势如何 | 慢在哪一段,调用了谁 |
| 数据结构 | 追加写的文本或 JSON | 带标签的数值 + 时间戳 | trace_id 聚合的 span 列表 |
| 成本随什么增长 | 请求数 × 每请求日志条数 | 时间序列数(label 基数) | span 数 × 采样率 × 保留期 |
| 典型失效模式 | 量大、缺关联、schema 漂移 | 高基数、平均值骗人、丢桶 | 采样丢错误、上下文断链、span 过细 |
| 查询方式 | 全文检索 + 字段过滤 | PromQL 聚合 | 按 trace_id 拉取整棵树 |
db.statement 是 SELECT ... FROM author WHERE id = ?,重复了 20 次;日志里那行 feed.build 的 author_ids 字段确认这一页里确实有 20 个不同作者——于是"批量查询"这个改法就有了依据,而不是拍脑袋。rate() 或 increase(),这两个函数会处理归零(counter reset)。命名惯例是加 _total 后缀,比如 http_requests_total。
Gauge(瞬时值):可增可减的当前值。正在处理的请求数、队列长度、连接池占用、内存使用量。它没有"累积"语义,所以不能对它求 rate,只能看当前值或 avg_over_time。
Histogram(直方图):客户端按预设的桶边界把观测值累加进一组累积计数器。它输出三样东西:每个桶的累积计数 _bucket{le="0.1"}、总和 _sum、总次数 _count。
Summary(摘要):客户端自己计算分位数,输出一组带 quantile 标签的 gauge,比如 {quantile="0.99"}。
现在说关键结论:延迟这类指标,必须用 Histogram,不能用 Summary,更不能用平均值。
理由不是"Histogram 更准",而是"Histogram 可聚合"。这是两种类型在数学结构上的差别:
le="0.1" 桶加起来,就是两实例合并后小于 100 毫秒的请求数。所以你可以先把所有实例、所有时间片聚合,再在聚合结果上用 histogram_quantile() 算分位数。from prometheus_client import Counter, Gauge, Histogram
HTTP_REQUESTS = Counter(
"http_requests_total",
"HTTP 请求总数",
["method", "route", "status_class"],
)
INFLIGHT = Gauge(
"http_inflight_requests",
"正在处理的请求数",
)
HTTP_DURATION = Histogram(
"http_request_duration_seconds",
"HTTP 请求耗时",
["method", "route"],
buckets=(0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0),
)
with HTTP_DURATION.labels(method="GET", route="/api/articles/feed").time():
render_feed(request)
Histogram.time() 是一个上下文管理器,进出各打一次时间戳,把差值塞进对应的桶。
算术平均 = (99 × 10ms + 1 × 10000ms) / 100 = (990 + 10000) / 100 = 109.9ms
histogram_quantile(0.99,
sum by (le) (rate(http_request_duration_seconds_bucket{route="/api/articles/feed"}[5m])
))
sum by (le) 把各实例的桶加起来,再算分位——顺序反了就退化成"平均各实例的 P99"。第二,histogram_quantile 在桶内做线性插值:它假设落在 (0.25, 0.5] 这个桶里的样本在 0.25 到 0.5 之间均匀分布,然后按比例估一个值出来。这意味着:
+Inf 桶里(所有桶都装不下),histogram_quantile 会返回该桶的上界之外的估计值,实际上等于"不知道"。这就是为什么桶的上界必须高于你的 SLO。scrape_interval 周期性地向每个目标的 /metrics 发 HTTP GET,把返回的文本解析成时间序列。配置长这样:
scrape_configs:
- job_name: article-api
scrape_interval: 15s
scrape_timeout: 10s
metrics_path: /metrics
static_configs:
- targets:
- "10.0.1.11:8000"
- "10.0.1.12:8000"
metric_relabel_configs:
- source_labels: [__name__]
regex: "go_.*"
action: drop
up == 0,你不需要额外的心跳指标就知道这个实例挂了。<namespace>_<subsystem>_<name>_<unit>,单位用基本单位后缀(秒用 _seconds,字节用 _bytes,不要用 _ms、_mb),Counter 加 _total。
接下来是label 基数。指标系统的成本几乎全部由时间序列数决定,而时间序列数由标签的取值组合决定。上界公式是:
序列数 ≤ 指标数 × Π(每个标签的取值个数)
method(5 个取值)、route(200 个路由)、status_class(8 个)、instance(20 个实例):
5 × 200 × 8 × 20 = 160,000 条序列
160,000 × 12 = 1,920,000 条序列
/api/articles/12345 和 /api/articles/12346 是两个不同的标签值。一个带 ID 的路径,基数等于资源总数。/api/articles/12345 归一成 /api/articles/:id。Django 里可以直接用 URL resolver 匹配出来的 route,而不是 request.path。status_class(2xx/3xx/4xx/5xx)而不是精确状态码,除非你确实要区分 401 和 403。metric_relabel_configs 里 drop 掉不需要的指标,或者用 labeldrop 去掉高基数标签。prometheus_tsdb_head_series,这个数字就是你当前的时间序列总数。它持续上涨而流量没涨,基本就是某个标签的取值在膨胀——最常见的是路由模板漏了,把 ID 带进去了。
trace_id。
http_request_duration_seconds_bucket{le="0.5",route="/api/articles/feed"} 8421
# {trace_id="4bf92f3577b34da6a3ce929d0e0e4736"} 0.481 1756000000.123
http_request_duration_seconds_bucket{le="1.0",route="/api/articles/feed"} 8426
# 开头那行是注释语法——这是 OpenMetrics 的兼容设计,老版本的解析器会把它当注释跳过,新版本会把它读成 exemplar。Prometheus 需要显式开启 exemplar 存储(启动参数 --enable-feature=exemplar-storage),存储量有上限,不是全量保留。
它的价值在于:Grafana 里那条 P99 曲线上,会散落着一些小圆点,每个点就是一条具体的 trace。你点一下,直接跳到追踪系统的那棵 span 树。从"P99 是 400 毫秒"到"这条请求的 400 毫秒花在哪",中间不需要任何手工猜测。
三个限制必须知道:
trace_id 作为 exemplar 标签是可以的(它只在该样本上存在,不进时间序列的标签维度),但长度要控制——32 个 hex 字符,别把整个 traceparent 塞进去。sum(rate(http_requests_total[5m]))。成功请求数 / 有效请求数,按什么算成功由你定义(状态码 200 且耗时小于 300 毫秒?还是只要不是 5xx?)。30 天 = 2,592,000 秒
不可用预算 = 2,592,000 × 0.001 = 2,592 秒 = 43 分 12 秒
99.95% → 1,296 秒 = 21 分 36 秒
99.99% → 259.2 秒 = 4 分 19 秒
trace_id 标识。一个 trace 是一棵 span 树。
span(跨度):树上的一个节点,代表一个有开始和结束的操作。它包含:
trace_id:属于哪条链路。span_id:自己的 ID,16 个 hex 字符。parent_span_id:父节点的 ID。根 span 没有父节点。name:操作名,比如 GET /api/articles/feed、SELECT author。kind:server、client、producer、consumer、internal。这个字段决定了它在瀑布图里怎么画,也决定了语义——一个 client span 应该有一个对应的远端 server span。http.method、db.system、db.statement、messaging.destination。exception、cache.miss。Unset、Ok、Error。注意 Unset 不等于成功,它只是"没有显式设置"。T,创建 span S1(网关自己的 server span);网关调内容服务,创建 client span S2,parent=S1;内容服务收到请求,从 header 里读到 T 和 S2,创建自己的 server span S3,parent=S2;内容服务查数据库,创建 client span S4,parent=S3。整棵树以 T 聚合。
这里有一个常见误解:parent_span_id 指的是"调用我的那个 span",不是"我上一个 span"。所以跨服务时,下游的根 span 的 parent 是上游的 client span,不是上游的 server span。这保证了瀑布图能把网络传输时间也画出来——上游 client span 的结束时间减去下游 server span 的开始时间,就是网络加排队的耗时。
baggage 是第四个概念,容易和 trace 混。它是随请求传播的一组键值对,W3C Baggage 规范定义,走独立的 baggage header,格式是 key1=value1,key2=value2(值需要百分号编码)。它的用途是业务上下文:租户 ID、灰度分组、实验桶。它不是 trace 的一部分,不会出现在 span 的 attributes 里,除非你手动读出来。
关于 baggage 有一条安全铁律:它是客户端可控的,不能用于鉴权或权限判断。任何从 baggage 里读出来的"用户角色"都可能是伪造的,因为它的源头是一个 HTTP header。它的正确用法是"传递提示信息",比如让下游知道该查哪个分库。
然后是 W3C Trace Context 的 traceparent,格式固定为四段,用 - 分隔:
00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
│ └────────── 32 hex ──────────┘ └── 16 hex ──┘ └flags┘
version trace-id parent-id trace-flags
version:两位。00 是当前规范版本。未来版本可能加字段,解析时要"遇到不认识的版本就丢弃整条 header",而不是猜。trace-id:32 个 hex 字符,128 bit。全零是非法值。parent-id:16 个 hex 字符,64 bit。它就是"调用方那个 span 的 span_id"。全零也是非法值。trace-flags:8 bit,目前只用最低位表示"是否采样"。01 表示采样,00 表示不采样。def parse_traceparent(value: str):
parts = value.split("-")
if len(parts) != 4:
return None
version, trace_id, parent_id, flags = parts
if version != "00":
return None
if len(trace_id) != 32 or len(parent_id) != 16:
return None
if trace_id == "0" * 32 or parent_id == "0" * 16:
return None
try:
int(trace_id, 16)
int(parent_id, 16)
flag_bits = int(flags, 16)
except ValueError:
return None
return trace_id, parent_id, flag_bits & 0x01
tracestate,用于厂商扩展(比如某个 APM 厂商的采样标记),格式是逗号分隔的 key=value,长度有上限。它和 baggage 的区别是:tracestate 是给追踪系统自己用的,baggage 是给业务代码用的。
跨服务传播的载体不止 HTTP header:消息队列要写进消息属性(Kafka headers、RabbitMQ headers、SQS message attributes),gRPC 走 metadata。只要有一个环节没传,链路就在那里断成两棵树。
20 × 10 × 86,400 = 17,280,000 个 span/天
trace-flags 的最低位,全链路复用。优点是成本几乎为零——决定一次,后续所有服务读 header 就知道采不采,不需要缓冲。缺点是决定得太早:请求刚进来时,你还不知道它会不会失败、会不会慢。
tail sampling(尾部采样) 在收集端做。所有 span 先上报到 collector,collector 按 trace_id 缓冲整棵树,等 trace 结束后再根据完整信息决定"留还是丢"。策略通常是"错误全留、慢请求全留、其余按比例"。这恰好补上了 head sampling 的盲区。
固定比例采样的盲区可以算出来。设错误率 p,采样率 r,请求数 N,那么被采到的错误 trace 期望数量是:
E[错误样本] = N × p × r
N = 1 / (p × r)
trace_id 做一致性哈希路由。Tracer、Span、Meter 这些抽象,业务代码只依赖这一层。没有实现时是空操作(no-op),不会报错也不会拖慢。TracerProvider 是全局单例,进程启动时创建一次,配置 sampler、exporter、resource(服务名、版本、实例 ID)。Tracer 从 provider 拿,通常按模块命名(get_tracer("article.feed"))。Span 从 tracer 创建,可以是 start_as_current_span(自动设为当前 span,退出时结束)或 start_span(手动管理)。Attribute 是 span 上的键值对,要遵守语义约定(http.request.method、db.system、db.namespace)。自己发明 my_sql_time 这种名字,数据就没法和别人的看板对齐。Event 是 span 内的瞬时事件,带时间戳。Status 是 Ok / Error,设置 Error 时应该同时 record_exception()。opentelemetry-instrumentation-django、-httpx、-psycopg 这类库,一个 instrument() 调用就全覆盖,而且它们自动处理上下文注入和提取。feed.rank(排序)、feed.hydrate(补作者信息)、risk.check(风控校验)。这些是"你的系统独有"的阶段,自动埋点看不见。from opentelemetry import trace
tracer = trace.get_tracer("article.api")
class FeedSpanMiddleware:
def __init__(self, get_response):
self.get_response = get_response
def __call__(self, request):
span = trace.get_current_span()
span.set_attribute("feed.page", request.GET.get("page", "1"))
span.set_attribute("feed.user_tier", getattr(request, "tier", "anon"))
with tracer.start_as_current_span("feed.hydrate") as child:
child.set_attribute("hydrate.strategy", "batch")
response = self.get_response(request)
child.set_attribute("hydrate.authors", getattr(request, "author_count", 0))
return response
trace.get_current_span() 拿到的是自动埋点创建的那个 span,start_as_current_span 创建的是它的子 span。不要在这里重新创建根 span——那会把链路切断成两棵树。
第二,给 httpx / requests 注入上下文。如果用了 opentelemetry-instrumentation-httpx,注入是自动的。手动注入的做法是:
from opentelemetry.propagate import inject
import httpx
headers = {}
inject(headers) # 把当前 span 的 traceparent 写进 dict
resp = httpx.get("http://author-svc/internal/authors", headers=headers)
inject 读的是当前的 context(contextvars),写的是 W3C 格式的 header。接收端用 extract 还原。这两个函数是跨服务不丢链路的唯一正确做法——手写 headers["traceparent"] = ... 很容易漏掉 tracestate,或者在异步上下文里拿错 span。
第三,给数据库查询加 span。自动埋点会给每次 execute 创建 span,但 SQL 里的参数默认不会记录(有隐私和体积问题)。如果你需要定位"哪条 SQL 慢",可以手动包一层,只记录语句模板和表名:
from opentelemetry import trace
tracer = trace.get_tracer("article.db")
def fetch_authors(conn, author_ids):
with tracer.start_as_current_span("db.author.batch") as span:
span.set_attribute("db.system", "postgresql")
span.set_attribute("db.operation", "SELECT")
span.set_attribute("db.collection.name", "author")
span.set_attribute("db.query.ids_count", len(author_ids))
with conn.cursor() as cur:
cur.execute(
"SELECT id, name FROM author WHERE id = ANY(%s)",
(author_ids,),
)
return cur.fetchall()
db.query.ids_count 这个属性是排查的关键——它让你在瀑布图上直接看到"这次批量查了 20 个 ID",而不是"一次查询"。
第四,异步上下文。这是最容易出问题的地方。OTel 的 Python SDK 用 contextvars 存当前 span,所以在 async def 里是对的;但如果你用 run_in_executor 把工作丢进线程池,contextvars 不会自动传过去,必须显式复制:
import asyncio, contextvars
ctx = contextvars.copy_context()
async def handle():
loop = asyncio.get_running_loop()
result = await loop.run_in_executor(None, ctx.run, blocking_work)
return result
BatchSpanProcessor,不要用 SimpleSpanProcessor:
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
from opentelemetry.sdk.resources import Resource
provider = TracerProvider(
resource=Resource.create({
"service.name": "article-api",
"service.version": "2026.11.04",
"deployment.environment": "prod",
})
)
provider.add_span_processor(
BatchSpanProcessor(
OTLPSpanExporter(endpoint="http://otel-collector:4317", insecure=True),
max_queue_size=2048,
schedule_delay_millis=5000,
)
)
trace.set_tracer_provider(provider)
BatchSpanProcessor 会攒一批再发,队列满了丢 span 并计数,但不阻塞业务线程。这个取舍是对的:观测不能拖垮业务。前提是你知道它在丢,否则会把"丢 span"误读成"这段时间没流量"。
histogram_quantile(0.50, sum by (le) (rate(http_request_duration_seconds_bucket{route="/api/articles/feed"}[5m]))
histogram_quantile(0.99, sum by (le) (rate(http_request_duration_seconds_bucket{route="/api/articles/feed"}[5m]))
(0.1, 0.25] 移到了 (0.25, 0.5],说明慢的这部分是"多花了两三百毫秒",而不是"卡住几十秒"。这个量级和"多查了十几次数据库"是吻合的,和"下游超时"不吻合(超时通常是秒级)。
第三步,从 exemplar 拿一条 trace_id。Grafana 上点那个落在高桶里的 exemplar 点,跳到追踪系统。瀑布图长这样:
GET /api/articles/feed 410ms server
├── feed.query_articles 22ms internal
├── feed.rank 18ms internal
├── feed.hydrate 355ms internal
│ ├── SELECT author (id=1) 17ms client
│ ├── SELECT author (id=2) 16ms client
│ ├── ... 共 20 次 ...
│ └── SELECT author (id=20) 18ms client
└── render.template 14ms internal
SELECT author,每次 16 到 18 毫秒。"单次不慢,串行很多次"——这正是开头说的那个形状。
第四步,属性定位。点开任意一个 SELECT author span,属性里有 db.system=postgresql、db.operation=SELECT、db.collection.name=author、db.query.ids_count=1。注意最后这个属性:如果它显示 1,说明代码是逐条查询;如果显示 20,说明已经是批量查询但批量本身慢。这一个属性就把"要不要改成批量"这个决策变成了事实判断。
第五步,日志确认参数。用 trace_id 去日志系统里捞:
trace_id=4bf92f3577b34da6a3ce929d0e0e4736
feed.build 那行有 author_ids=[1,2,...,20] 和 page_size=20。到这里,"这一页有 20 个不同作者,代码给每个作者单独查了一次"这个事实链就完整了。修复方案是 WHERE id = ANY(%s) 一次查完,20 次往返变成 1 次。
这个链路里,每一步都不可或缺:
import logging
from opentelemetry import trace
class TraceContextFilter(logging.Filter):
def filter(self, record):
ctx = trace.get_current_span().get_span_context()
if ctx.is_valid:
record.trace_id = format(ctx.trace_id, "032x")
record.span_id = format(ctx.span_id, "016x")
else:
record.trace_id = "-"
record.span_id = "-"
return True
logging.getLogger().addFilter(TraceContextFilter())
%(trace_id)s。日志系统(Loki、ELK、CloudWatch)都能按这个字段建索引或过滤。这里的顺序很重要:先有 trace_id,日志才有聚合维度;如果只有 request_id,你在追踪系统里搜不到它。
一个容易被忽略的点:日志里写的 trace_id 必须是"当前 span"的,不是"根 span"的。如果你在 hydrate 的子 span 里打日志,写根 trace_id 是对的(聚合用),但写根 span_id 就丢了"这行日志属于哪个阶段"。两个都写:trace_id 用于聚合,span_id 用于在瀑布图上对齐。
总成本 ≈ 序列数 × 单序列开销 + 样本数 × 单样本开销
--storage.tsdb.retention.time(比如 15 天)和 --storage.tsdb.retention.size(比如 100 GB),两个都设,谁先到谁生效。本地 TSDB 不适合长期保留——它不是为多年归档设计的。长期方案是 remote_write 到 Thanos、Mimir、VictoriaMetrics 这类系统,本地只留几天做快速查询。
追踪的存储成本由三个因子相乘决定:
span 数/天 × 采样率 × 平均 span 体积 × 保留天数
db.statement 带完整 SQL、http.url 带 query string,都会让压缩率崩掉。记语句模板和参数个数,参数值走日志。
治理清单,按投入产出排序:
prometheus_tsdb_head_series 和每个指标的序列数,是判断"要不要治理"的唯一依据。request.path 换成路由模板。这一条通常能砍掉一个数量级。| 问题 | 工具 | 关键约束 |
|---|---|---|
| 有多慢、多常见 | Histogram + P95/P99 | 桶要覆盖 SLO;样本量要够;先 sum by (le) 再算分位 |
| 慢在哪一段 | trace 的 span 树 | 上下文必须跨服务传播;span 粒度要克制 |
| 那一段里发生了什么 | 日志 + trace_id | trace_id 要写进日志;参数才在日志里 |
| 是哪一条请求 | exemplar | 只对 Histogram 有意义;是抽样不是全量 |
| 成本为什么涨 | label 基数 / span 数 / 保留期 | 基数是一切成本的乘数 |
1/(p×r) 算出来:你的 SLO 越严,这个盲区越大,而它恰好盖住了你最需要看的那部分请求。专题:后端架构 — Django、并发、限流、灰度与线上部署