开发者经常问我这个问题：“为什么我需要 trace？我有日志啊。”多年来我也问过同样的问题。
简短的回答是：一行日志记录的是某个时间点发生了某件事。而一个 span 记录的是一个操作，带有 trace ID、span ID、父 span ID 以及开始和结束时间。这些字段能告诉你哪些操作属于同一个请求、谁调用了谁，以及时间花在了哪里。普通日志不携带这些信息，所以你最终只能靠猜。
详细的回答演示起来比解释起来更容易。
一个耗时两秒的结账
这是一个结账处理程序。它会并发加载购物车和折扣信息，然后向用户收费。三个用户同时结账，其中一位用户的折扣服务响应很慢。
import asyncio
import logging
import random
logging.basicConfig(format="%(asctime)s %(levelname)s %(message)s", level=logging.INFO)
logger = logging.getLogger("checkout")
async def fetch_cart(user_id: int) -> list[str]:
await asyncio.sleep(random.uniform(0.05, 0.1))
logger.info("cart loaded")
return ["book", "mug"]
async def fetch_discounts(user_id: int) -> float:
await asyncio.sleep(2.0 if user_id == 2 else random.uniform(0.05, 0.1))
logger.info("discounts loaded")
return 0.1
async def charge(user_id: int, items: list[str], discount: float) -> None:
await asyncio.sleep(random.uniform(0.1, 0.2))
logger.info("payment charged")
async def checkout(user_id: int) -> None:
logger.info("checkout started")
items, discount = await asyncio.gather(fetch_cart(user_id), fetch_discounts(user_id))
await charge(user_id, items, discount)
logger.info("checkout finished")
async def main() -> None:
await asyncio.gather(*(checkout(user_id) for user_id in (1, 2, 3)))
asyncio.run(main())
输出如下：
2026-10-19 11:15:13,441 INFO checkout started
2026-10-19 11:15:13,441 INFO checkout started
2026-10-19 11:15:13,441 INFO checkout started
2026-10-19 11:15:13,493 INFO cart loaded
2026-10-19 11:15:13,494 INFO cart loaded
2026-10-19 11:15:13,503 INFO discounts loaded
2026-10-19 11:15:13,506 INFO cart loaded
2026-10-19 11:15:13,527 INFO discounts loaded
2026-10-19 11:15:13,605 INFO payment charged
2026-10-19 11:15:13,606 INFO checkout finished
2026-10-19 11:15:13,659 INFO payment charged
2026-10-19 11:15:13,659 INFO checkout finished
2026-10-19 11:15:15,442 INFO discounts loaded
2026-10-19 11:15:15,588 INFO payment charged
2026-10-19 11:15:15,588 INFO checkout finished
一次结账大约花了两秒。是哪个用户？最后一行“checkout finished”属于三行“checkout started”中的哪一行？日志无法说明。
三个请求时，你眯着眼还能推算出来。但每秒三百个请求时，不同请求的日志行会交错在一起，你就无法分辨了。
添加请求 ID
通常的解决办法是使用请求 ID。你把它存进一个 contextvars.ContextVar ，并通过过滤器把它加到每条日志记录中。这取代了第一个示例中的 logging.basicConfig 调用：
import contextvars
import logging
import uuid
request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")
class RequestIDFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
record.request_id = request_id.get()
return True
handler = logging.StreamHandler()
handler.addFilter(RequestIDFilter())
logging.basicConfig(format="%(asctime)s %(request_id)s %(message)s", level=logging.INFO, handlers=[handler])
然后 checkout 调用 request_id.set(uuid.uuid4().hex[:8]) 在其第一行日志之前。 asyncio 将上下文复制到每个任务中，因此 fetch_cart 和 fetch_discounts 看到相同的 ID：
2026-10-19 11:16:29,713 16bac7c6 checkout started
2026-10-19 11:16:29,791 16bac7c6 cart loaded
2026-10-19 11:16:31,714 16bac7c6 discounts loaded
2026-10-19 11:16:31,816 16bac7c6 payment charged
2026-10-19 11:16:31,817 16bac7c6 checkout finished
这样好多了。你可以按 16bac7c6 进行筛选，并看到单个请求。不过，要读取它，你还得减去时间戳。
“购物车加载完成”和“折扣加载完成”之间的间隔是 1.9 秒。但这并不是折扣加载所花的时间。两个调用是同时开始的，所以折扣花了 2.0 秒，而购物车只花了 78 毫秒。两行日志之间的每一段间隔都被归因于其间运行的某段代码，而日志并没有指明是哪段代码。一个没人记录日志的阻塞调用，看起来和一个缓慢的折扣服务一模一样。
“但我有带请求 ID 的结构化日志”
这是我听到最多的回答，而且它确实不错。假设每一行都是 JSON，每个服务都传递请求 ID，每个操作在完成时都记录日志。这是同一个程序使用 JSON 格式化器时的慢结账：对于这个请求来说，这就足够了。它显示折扣花了 2001 毫秒。如果你所有的请求都像这个一样，那就继续用日志吧。但在三种情况下它就不够用了。同一操作运行两次。假设在超时后重试，或者结账为每个商品加载一次折扣。现在这个请求有两行日志。请求 ID 表明两者都属于这个请求。但它没有说明哪一个在等待，或者哪一个调用在…… duration_ms 完成时。这是同一个程序使用 JSON 格式化器时的慢结账：
{"ts": "11:37:35.684", "request_id": "5adf2211", "event": "checkout started", "user_id": 2}
{"ts": "11:37:35.765", "request_id": "5adf2211", "event": "cart loaded", "duration_ms": 81}
{"ts": "11:37:37.685", "request_id": "5adf2211", "event": "discounts loaded", "duration_ms": 2001}
{"ts": "11:37:37.828", "request_id": "5adf2211", "event": "payment charged", "duration_ms": 142}
{"ts": "11:37:37.828", "request_id": "5adf2211", "event": "checkout finished", "duration_ms": 2144}
对于这个请求来说，这就足够了。 duration_ms 它显示折扣花了 2001 毫秒。如果你所有的请求都像这个一样，那就继续用日志吧。
在三种情况下它就不够用了。
同一操作运行两次
假设 fetch_discounts 在超时后重试，或者结账为每个商品加载一次折扣。现在这个请求有两 discounts loaded 行。请求 ID 表明两者都属于这个请求。但它没有说明哪一个 charge 在等待，或者结账流程中哪个调用产生了每一条日志。为此，每个操作都需要有自己的 ID 以及其调用者的 ID。
该操作永远不会完成
duration_ms 会在操作结束时写入。如果折扣服务一直挂起，直到客户端放弃，或者进程被杀掉，那么这个请求就只有一行 checkout started 行，仅此而已。你知道出了问题，但不知道出在哪里。当 Logfire SDK 会启动一个 span，它可以发送一个 ，这样即使操作从未完成，也会有该操作及其父级的记录。你的库不知道你的请求 ID 你的 HTTP 客户端、数据库驱动和支付 SDK 都不知道你的 字段。另一个团队的服务可能把它叫作 。请求 ID 只覆盖你写的那些日志行。OpenTelemetry 插桩也覆盖了这些库，而且 OpenTelemetry SDK 默认读写同一个 请求头。要解决这些问题，就需要更多字段：每个操作的 ID、其调用者的 ID、一个“已开始”事件，以及一个这样，即使操作从未完成，也会有该操作及其父级的记录。
你的库不会记录你的请求 ID
你的 HTTP 客户端、数据库驱动和支付 SDK 都不知道你的 request_id 字段。另一个团队的服务可能会把它称为 correlation_id请求 ID 覆盖了你写的那些日志行。OpenTelemetry 插桩也覆盖了这些库，而且 OpenTelemetry SDK 默认读写同一个 traceparent 默认情况下，请求头。
要解决这些问题，就需要更多字段：每个操作的 ID、其调用者的 ID、一个“已开始”事件，以及一个在服务之间传递这些 ID 的请求头。以下是你构建的内容：
| 你添加到日志中的内容 | OpenTelemetry 的对应方案 |
|---|---|
| 请求 ID | trace_id |
| 操作 ID | span_id |
| 调用方的操作 ID | parent_span_id |
“已开始”事件以及 duration_ms |
span start_time 以及 end_time |
| 一个包含请求 ID 和调用操作 ID 的请求头 | traceparent 请求头，其中包含 trace_id 以及调用者的 span_id |
这些就是 span 的各个字段，靠手工维护在你的日志记录里。你一个字段一个字段地重新发明了追踪，既没有标准格式，也没有能理解它的工具。
最后一行的请求头已经是一个标准。 W3C Trace Context 定义 traceparent，它在服务之间携带 trace ID 和调用方的 span ID：
traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01
用于 HTTP 客户端和服务器的 OpenTelemetry 插桩会读写它，因此你无需自己处理。
带有 span 的同一段代码
下面是再次给出的结账过程，其中带有 Pydantic Logfire每个函数都是一个 span，通过 @logfire.instrument要运行它，请安装 Logfire，命令为 pip install logfire 并进行身份验证，使用 logfire auth，正如 入门指南 描述：
import asyncio
import random
import logfire
logfire.configure(service_name="checkout")
@logfire.instrument("fetch cart")
async def fetch_cart(user_id: int) -> list[str]:
await asyncio.sleep(random.uniform(0.05, 0.1))
return ["book", "mug"]
@logfire.instrument("fetch discounts")
async def fetch_discounts(user_id: int) -> float:
await asyncio.sleep(2.0 if user_id == 2 else random.uniform(0.05, 0.1))
return 0.1
@logfire.instrument("charge")
async def charge(user_id: int, items: list[str], discount: float) -> None:
await asyncio.sleep(random.uniform(0.1, 0.2))
@logfire.instrument("checkout {user_id=}")
async def checkout(user_id: int) -> None:
items, discount = await asyncio.gather(fetch_cart(user_id), fetch_discounts(user_id))
await charge(user_id, items, discount)
async def main() -> None:
await asyncio.gather(*(checkout(user_id) for user_id in (1, 2, 3)))
asyncio.run(main())
没有请求 ID，没有过滤器，也没有“已开始”这一行。每次结账都有自己的 trace。这些是那个慢请求的 span。最后三个是以下 span 的子级： checkout span：
| Span | 开始 | 持续时间 |
|---|---|---|
| checkout user_id=2 | 0 毫秒 | 2176 毫秒 |
| 获取购物车 | 0 毫秒 | 69 毫秒 |
| 获取折扣 | 2001 毫秒 | 2001 毫秒 |
| 收费 | 2002 毫秒 | 174 毫秒 |
Logfire 会将这些绘制成瀑布图，但表格已经回答了这个问题。 fetch cart ，而 fetch discounts 并行运行，折扣耗时 2001 毫秒，而 charge 只有在两者都完成后才开始。你没有减去任何东西。
你可以跨请求提出的问题
一次缓慢的请求就是一次调试过程。接下来的问题通常是“这种情况多久发生一次，发生在哪里？”用日志时，你要从消息字符串中解析出时长。用 span 时， duration 是一列。
Logfire 将已完成的 span 存储在一个 records 你可以查询的表格，使用 SQL:
SELECT
span_name,
count(*) AS calls,
approx_percentile_cont(duration, 0.95) AS p95_seconds
FROM records
WHERE service_name = 'checkout' AND kind = 'span'
GROUP BY span_name
ORDER BY p95_seconds DESC
这样你就能得到结账流程中每个步骤的 p95。按 parent_span_id IS NULL 以获取完整的结账记录，或按 attributes->>'user_id' 按用户拆分它们。
没人写下的那些行
日志只包含有人决定记录的内容。如果没有人记录数据库查询，那么它就是两个时间戳之间的一段空白。
插桩库会为你没有编写的代码创建 span。在 Logfire 中，每个库只需一行：
logfire.instrument_fastapi(app)
logfire.instrument_httpx()
logfire.instrument_asyncpg()
每个请求、发出的 HTTP 调用和 SQL 查询都会变成一个带有持续时间和父级的 span。HTTPX 和 FastAPI 插桩还会写入和读取 traceparent 请求头，因此一个跨越三个服务的请求就是一条 trace。
保留你的日志
trace 并不能取代日志。有些东西是事件，而不是操作：一次缓存未命中、一个重试决策、一条校验警告。它们没有持续时间，而日志行才是适合它们的形态。
变化在于，span 内的日志行会获得该 span 的上下文。将标准库日志发送到 Logfire，只需使用 LogfireLoggingHandler:
import logging
import logfire
logfire.configure()
logging.basicConfig(handlers=[logfire.LogfireLoggingHandler()], level=logging.INFO)
logger = logging.getLogger("checkout")
with logfire.span("checkout {user_id=}", user_id=2):
logger.info("discounts loaded")
discounts loaded 存储为以下 span 的子级： checkout span，并带有相同的 trace ID。你现有的 logger.info 调用继续正常工作，而且现在每一次调用都会说明它来自哪个请求。
那么，如果你有日志，还需要 trace 吗？如果你的日志已经带有请求 ID、操作 ID、调用方的操作 ID 以及开始和结束时间，那么你就拥有了 trace 的数据，只是以文本形式存储。Span 在 OpenTelemetry 格式中携带相同的字段，追踪后端会读取这些字段，而 Logfire 还允许你将其作为 SQL 列.
在 Google 搜索中查看更多来自 Pydantic 的内容
将 Pydantic 添加为首选来源，以便更容易找到我们的最新文章。
在 Google 上选择 Pydantic 作为首选来源（在新标签页中打开）准备好看看你的 agent 实际在做什么了吗？
免费开始 免费开始 联系我们 联系我们探索我们的开源软件包
