OpenTelemetry 从埋点到排障

程序出问题的时候，日志通常是最先被翻出来的东西。

它能告诉我请求进来了，也能告诉我某个函数报错了，但当一个异步接口偶尔慢两秒时，日志很快就不够用了：到底是排队等了 1.5 秒，还是外部请求慢了 1.5 秒？是一个任务拖住了整个批次，还是所有任务都变慢了？如果一次请求又经过了重试和超时，几行时间戳很难把这段过程拼回来。

这篇文章从一个只有日志的 Python 异步服务开始，给它加上 OpenTelemetry。过程分三步：先用自动埋点快速看到框架和库的调用，再给业务任务加手动 span，最后补上指标和一次完整的排障过程。示例重点是思路和边界，不依赖某个商业观测平台，也不把演示数据当成生产结论。

先把三种信号分开

我以前把日志、耗时和错误都塞在一条字符串里，出了问题再用正则表达式找线索。可观测性真正有用的地方，是把不同问题交给不同信号：

信号	它回答的问题	适合保存什么
Trace	这一次请求具体经过了哪些步骤	父子调用、耗时、异常、上下文
Metrics	最近一段时间整体变成什么样了	请求量、延迟分布、活跃任务数
Logs	某个时刻程序说了什么	详细错误、状态变化、调试信息

OpenTelemetry Python 当前把 Traces 和 Metrics 标为 Stable，Logs 仍是 Development，所以本文把主线放在 Trace 和 Metrics 上，不把“已经能采集日志”写成“日志系统已经解决了”。官方 Python 状态说明

一个能跑，但只能靠猜的异步服务

先看最小版本。这里不用真实股票接口，只用不同的睡眠时间模拟外部依赖，这样观察到的差异来自程序结构，而不是网络波动。

import asyncio
from time import perf_counter


DEPENDENCY_DELAY = {
    "fast": 0.05,
    "slow": 0.35,
    "retry": 0.12,
}


async def fetch_quote(kind: str) -> dict[str, str | float]:
    await asyncio.sleep(DEPENDENCY_DELAY[kind])
    return {"kind": kind, "value": 100.0}


async def handle_batch(kinds: list[str]) -> dict[str, object]:
    started = perf_counter()
    tasks: list[asyncio.Task[dict[str, str | float]]] = []

    async with asyncio.TaskGroup() as group:
        for kind in kinds:
            tasks.append(group.create_task(fetch_quote(kind)))

    elapsed_ms = (perf_counter() - started) * 1000
    return {
        "elapsed_ms": round(elapsed_ms, 1),
        "items": [task.result() for task in tasks],
    }


async def main() -> None:
    result = await handle_batch(["fast", "slow", "retry"])
    print(result)


asyncio.run(main())

这个函数最终会输出一个总耗时，但它没有记录每个任务的开始和结束时间。哪怕我把 print() 加到 fetch_quote() 里，也只能看到几行互相交错的文字，无法在一次请求和另一次请求之间建立可靠的父子关系。

第一步不是把每一行日志都换成 span，而是先问清楚：我想定位哪一种慢？这个例子里至少有三种：任务等待、依赖调用和重试等待。

自动埋点：先把框架层看见

OpenTelemetry Python 提供了零代码埋点路线。官方文档推荐先安装发行包，然后让 bootstrap 根据当前环境安装可用的 instrumentation library：

1 2	python -m pip install opentelemetry-distro opentelemetry-exporter-otlp opentelemetry-bootstrap -a install

启动时通过环境变量指定服务名和导出器。开发阶段先导出到控制台，少引入一个观测后端：

$env:OTEL_SERVICE_NAME = "quote-service"
$env:OTEL_TRACES_EXPORTER = "console"
$env:OTEL_METRICS_EXPORTER = "none"
$env:OTEL_LOGS_EXPORTER = "none"
opentelemetry-instrument python app.py

Linux 或 macOS 可以使用同名环境变量，只是设置方式不同。自动埋点的优点是接入快，HTTP 框架、数据库客户端和常用网络库如果有对应的 instrumentation，通常不用改业务代码就能看到一部分调用链。Python 零代码埋点文档

但它也有明确的边界。自动埋点通过运行时修改已支持库的函数来工作，它不知道“等待队列”是业务瓶颈，也不知道一次重试应该属于哪个领域操作。只靠自动生成的 HTTP span，最后通常只能得到“某个请求慢”，得不到“哪个任务阶段慢”。

这一步适合做覆盖面，不适合代替业务建模。

手动埋点：给真正重要的动作命名

先初始化一个最小的 TracerProvider。控制台导出适合本地调试；生产环境一般会使用批量处理器，再通过 OTLP 发送到 Collector。

from opentelemetry import trace
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    BatchSpanProcessor,
    ConsoleSpanExporter,
)


resource = Resource.create({
    "service.name": "quote-service",
    "service.version": "0.1.0",
})
provider = TracerProvider(resource=resource)
provider.add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)
trace.set_tracer_provider(provider)
tracer = trace.get_tracer("quote-service")

然后把外部依赖包起来。这里的 span 名称描述动作，不直接使用用户输入；属性也只放低基数、对排障有用的内容。

from opentelemetry.trace import Status, StatusCode


async def fetch_quote(kind: str) -> dict[str, str | float]:
    with tracer.start_as_current_span(
        "dependency.quote",
        attributes={"dependency.kind": kind},
    ) as span:
        try:
            await asyncio.sleep(DEPENDENCY_DELAY[kind])
            return {"kind": kind, "value": 100.0}
        except TimeoutError as exc:
            span.record_exception(exc)
            span.set_status(Status(StatusCode.ERROR))
            raise

再给批次和单个任务建立父子关系：

async def handle_batch(kinds: list[str]) -> dict[str, object]:
    with tracer.start_as_current_span(
        "batch.process",
        attributes={"batch.size": len(kinds)},
    ):
        tasks: list[asyncio.Task[dict[str, str | float]]] = []
        async with asyncio.TaskGroup() as group:
            for kind in kinds:
                tasks.append(
                    group.create_task(fetch_quote(kind))
                )
        return {"items": [task.result() for task in tasks]}

当 TaskGroup 创建子任务时，当前上下文会成为子任务的起点，因此 Trace 里可以看到 batch.process 包住多个 dependency.quote。不过这不是“加了 asyncio 就自动万事大吉”：脱离请求生命周期的后台任务、自己创建的线程和跨进程消息，都需要单独验证上下文是否正确传递。异步任务的取消和生命周期仍然要按上一篇文章的方式明确管理，Trace 只是把这段生命周期呈现出来。Python asyncio 官方文档

指标：把一次慢请求变成趋势

Trace 能解释一次请求，不能单独告诉我过去一小时的 p95 延迟。指标只保留三个就够开始：请求总数、请求延迟和当前活跃任务数。

from time import perf_counter

from opentelemetry import metrics


meter = metrics.get_meter("quote-service")
request_count = meter.create_counter(
    "quote.requests",
    unit="{request}",
    description="Number of batch requests",
)
request_latency = meter.create_histogram(
    "quote.request.duration",
    unit="ms",
    description="Batch request duration",
)
active_tasks = meter.create_up_down_counter(
    "quote.tasks.active",
    unit="{task}",
    description="Number of active worker tasks",
)


async def observed_batch(kinds: list[str]) -> dict[str, object]:
    started = perf_counter()
    request_count.add(1, {"route": "/batch"})
    active_tasks.add(1, {"route": "/batch"})
    try:
        return await handle_batch(kinds)
    finally:
        active_tasks.add(-1, {"route": "/batch"})
        request_latency.record(
            (perf_counter() - started) * 1000,
            {"route": "/batch"},
        )

这里有两个容易混淆的地方。

第一，指标属性不能放任意输入。把完整 URL、用户 ID 或错误消息放进标签，会让时间序列数量不断增长；这些信息适合放在 Trace 或经过脱敏的日志里。第二，BatchSpanProcessor 和指标导出都可能在后台进行，应用退出时要调用 provider 的 shutdown/flush，不能让程序一结束，最后几秒的数据也跟着消失。

OTLP 和 Collector：把应用与后端隔开

本地控制台适合确认埋点是否存在，真正运行时，我更愿意让应用只负责生成遥测数据，把发送、批处理和路由交给 Collector。OpenTelemetry Collector 是厂商无关的接收、处理和导出组件，可以把同一份 OTLP 数据转到不同的后端。Collector 官方文档

一条典型链路是：

Python SDK
   │ OTLP / HTTP 或 gRPC
   ▼
OpenTelemetry Collector
   ├── batch processor
   ├── sampling / redaction
   └── exporter
        ├── Trace 后端
        └── Metrics 后端

官方 Python exporter 文档同时提供 OTLP 的 HTTP/protobuf 和 gRPC 路线，并建议生产环境使用 Collector；文章里不把某个后端当成唯一答案，读者可以先用 Console，再换成自己的 OTLP endpoint。Python Exporters 文档

一次排障：总耗时不是瓶颈名称

下面是一组演示数据，不代表真实线上测量。请求表面上用了 2.08 秒，普通日志只留下了开始和结束：

1 2	request started route=/batch request finished elapsed_ms=2080

Trace 展开以后，时间被拆成了几段：

Span	耗时	看到的事实
`batch.process`	2080 ms	整个批次的生命周期
`dependency.quote`（fast）	52 ms	正常返回
`dependency.quote`（retry）	410 ms	第一次失败后等待重试
`dependency.quote`（slow）	1610 ms	外部依赖占据主要时间

这时“把并发度从 3 调到 10”就不一定是正确修复。它可能让外部依赖更快触发限流，也可能让同时等待的任务更多。更可靠的做法是先给依赖调用加明确超时，再把重试等待和实际请求分成两个 span；如果 p95 只在并发升高时变差，再结合 active_tasks 指标判断是不是队列或下游容量问题。

可观测性没有替我做决定，它只是把一个模糊的“接口慢”拆成了几个可以验证的假设。

语义约定比自创字段更重要

如果每个项目都用 url、path、request_url 表示不同东西，换后端或合并仪表盘时很快会失去可比性。OpenTelemetry 的 Semantic Conventions 为 HTTP、数据库、消息队列和异常等场景定义了公共属性，应该优先使用标准字段，再补充少量业务属性。Semantic Conventions

我会把自定义属性限制在三类：

可以枚举的业务类型，例如 dependency.kind=quote；
有明确范围的状态，例如 retry.count=1；
对定位问题确实有帮助、且不会暴露隐私的标识。

像完整请求体、Cookie、Token、用户手机号这种数据，不应该因为“排查方便”就直接进 Trace。观测系统一旦保存了它们，后续的权限、保留期限和删除流程都会变复杂。

这套方案最容易踩的坑

没有设置 `service.name`

多个服务共用一个默认名称时，Trace 列表会变成一锅粥。服务名、版本和部署环境应该作为 Resource 属性，在应用启动时一次设置好。

只装自动埋点，不给业务动作命名

能看到 HTTP 请求不等于能看懂业务流程。队列等待、批处理、重试和缓存命中率都需要手动建模。

为每个输入创建高基数指标

Trace 可以带少量请求上下文，Metrics 的标签必须更加克制。否则指标后端的成本和查询速度会先出问题。

导出器影响了业务请求

观测数据发送失败不能阻塞主流程。生产环境需要批量导出、超时、重试和队列上限；Collector 本身也要限制权限和网络暴露范围。

只看平均延迟

平均值很容易掩盖少数慢请求。至少同时观察 p50、p95、p99，并从 Trace 中抽样检查尾部请求到底卡在哪一层。

忽略采样和数据版本

全量 Trace 可能很贵，过度采样又会漏掉偶发问题。采样规则、保留期限和敏感字段处理应该写进部署配置，而不是留在某个人的记忆里。

上线前我会检查什么

在把这套配置放进真实服务之前，我会逐项确认：

Trace、Metrics 和 Logs 的职责是否分清；
service.name、版本和环境是否正确；
自动埋点的库版本是否与应用依赖兼容；
关键业务阶段是否有手动 span；
span 和指标属性里没有密码、Token、Cookie 和高基数用户数据；
导出失败、Collector 不可用时，主业务仍然可以继续；
应用正常退出时会 flush 最后一批数据；
有一条从请求到下游依赖的 Trace 可以在测试环境完整走通。

最后的话

OpenTelemetry 最有价值的地方，不是让页面上多出几张漂亮的图，而是逼着我给“慢”重新命名。

它可能是队列等待，可能是外部请求，可能是重试策略，也可能是任务取消之后没有及时释放资源。日志仍然重要，指标也不会替代 Trace，但三者各自回答不同问题以后，排障才不需要完全依赖猜测。

这篇文章使用的是本地演示结构，真实服务还需要单独设计采样、权限、保留期限、告警和成本控制。OpenTelemetry 的组件稳定性和具体 instrumentation 支持范围也会随版本变化，升级前应以官方文档和实际依赖测试结果为准。