第3章日志与监控、链路追踪¶

学习目标¶

理解可观测性三支柱（日志、指标、追踪）的分工与协同
掌握结构化日志规范，能用 loguru 输出可被采集的日志
学会用 Prometheus + Grafana 搭建指标监控与告警
掌握 OpenTelemetry 的核心概念，能为 Agent 链路加追踪
理解告警体系的设计原则，避免告警风暴
能够用 Python 为一个 Agent 接口同时接入日志、指标、追踪

问题导入¶

凌晨 3 点，客服反馈"Agent 回答变慢了"。你打开服务器，看到满屏 print 出来的日志，没有时间戳、没有请求 ID、没有上下文。你试着 grep 一个用户 ID——什么都没搜到，因为日志里压根没记用户。你去看 CPU、内存——都正常。到底是哪一步慢？是 Embedding 检索慢、LLM 推理慢、还是某个工具调用卡住了？无从得知。

这就是"不可观测"的痛。生产系统必须有"眼睛"：日志告诉你"发生了什么"，指标告诉你"整体怎么样"，追踪告诉你"这一请求经历了什么"。三者合称可观测性三支柱。对 Agent 系统尤其关键——一次请求可能跨越检索、多个 LLM 调用、工具执行，链路极长，没有追踪根本无法定位瓶颈。本章带你把这三根支柱立起来。

核心概念¶

1. 可观测性三支柱¶

支柱	关注问题	数据特征	典型工具
日志（Logs）	发生了什么？	离散事件，带时间戳	ELK、Loki、loguru
指标（Metrics）	整体趋势如何？	时序数值，可聚合	Prometheus、Grafana
追踪（Traces）	单次请求怎么走的？	跨服务的有向树	OpenTelemetry、Jaeger

三者关系：指标用于"发现异常"（如错误率升高），追踪用于"定位到哪条链路"，日志用于"看清那条链路的细节"。一个故障排查的标准流程：告警（指标）→ 找到慢请求 trace_id → 用 trace_id 串起所有日志。

2. 结构化日志规范¶

传统 print 或纯文本日志难以被机器解析。结构化日志输出 JSON，每条日志是一个键值对集合，便于 ELK/Loki 采集与查询。Agent 系统的日志规范建议包含以下字段：

timestamp：ISO 8601 时间戳
level：DEBUG/INFO/WARNING/ERROR
service：服务名（如 agent-api）
trace_id / span_id：链路追踪上下文（关键！）
user_id / request_id：业务上下文
event：事件类型（如 llm_call、retrieval、tool_exec）
duration_ms：耗时
message：人类可读描述
extra：扩展字段（如 model、tokens、cost）

日志分级原则：ERROR 是"必须立即处理"（如 DB 连不上）；WARNING 是"需关注"（如缓存命中率下降）；INFO 是"关键业务事件"（如任务完成）；DEBUG 是"调试用"，生产默认关闭。切忌把所有事都记成 ERROR。

3. Prometheus 指标监控¶

Prometheus 是拉模式（pull）的时序数据库：它主动去各服务的 /metrics 端点抓取指标。指标分四类：

Counter：单调递增（如请求总数、错误总数）
Gauge：可增可减（如队列长度、内存占用）
Histogram：分布（如请求延迟分桶）
Summary：分位数（如 P95、P99 延迟）

Agent 系统必监控的黄金指标：请求速率（QPS）、错误率、延迟分布（P50/P95/P99）、LLM 调用耗时与 Token 消耗、队列积压、缓存命中率。

4. OpenTelemetry 链路追踪¶

OpenTelemetry（OTel）是 CNCF 主推的可观测性标准，统一了追踪、指标、日志的采集协议。追踪的核心概念：

Trace：一次完整请求的执行树，由唯一 trace_id 标识。
Span：树中的一个节点，代表一段操作，有 span_id、起止时间、属性、状态。
SpanContext：在服务间传递的上下文（trace_id + span_id），通过 HTTP header 或消息 header 注入/提取。
Span 间关系：根 Span → 子 Span，形成父子树。

一次 Agent 请求的 Trace 可能长这样：handle_request（根）→ retrieve_docs（检索）→ embed_query → vector_search → llm_call（推理）→ tool_exec（工具）。每个 Span 记录耗时与关键属性（模型名、检索命中文档数），一眼看清哪一步最慢。

5. 告警体系¶

好告警的三个特征：可执行（收到知道该干嘛）、及时（在用户感知前触发）、低噪声（不频繁误报）。设计原则：

基于 SLO 告警（如"错误率 5 分钟内 > 5%"），而非单点阈值。
分级：P0 电话、P1 短信、P2 IM 通知。
设抑制与聚合窗口，避免同一故障刷屏。
必须有 runbook（处置手册）链接。

原理图¶

flowchart TB
    subgraph 应用层
        APP[Agent 服务<br/>FastAPI]
        APP -->|结构化日志| LOGS[Logs]
        APP -->|/metrics 端点| METRICS[Metrics]
        APP -->|OTel SDK 上报| TRACES[Traces]
    end

    subgraph 采集层
        LOGS --> COLLECTOR_L[Promtail/Filebeat]
        METRICS --> PROM[Prometheus<br/>拉模式 pull]
        TRACES --> OTEL_COL[OTel Collector]
    end

    subgraph 存储与可视化
        COLLECTOR_L --> LOKI[(Loki/ES<br/>日志存储)]
        PROM --> GRAFANA[Grafana<br/>仪表盘+告警]
        OTEL_COL --> JAEGER[(Jaeger/Tempo<br/>追踪存储)]
    end

    GRAFANA -->|告警| ALERT[告警通道<br/>电话/短信/IM]
    GRAFANA -.统一查询.-> LOKI
    GRAFANA -.跳转 trace.-> JAEGER

    subgraph 排查流程
        ALERT -->|1.看指标| GRAFANA
        GRAFANA -->|2.定位慢请求<br/>拿 trace_id| JAEGER
        JAEGER -->|3.用 trace_id<br/>查日志| LOKI
    end

图：可观测性三支柱架构。应用同时输出日志、指标、追踪，经各自采集器进入存储；Grafana 作为统一面板串联三者——告警触发后，看指标定位异常 → 跳 Jaeger 看 trace → 用 trace_id 查日志看细节。

示例代码¶

下面用一个完整示例展示：如何为 Agent 接口同时接入结构化日志（loguru）、Prometheus 指标、OpenTelemetry 追踪，并把三者用 trace_id 串联。

# observability.py —— 可观测性配置
import os
from loguru import logger
from opentelemetry import trace, metrics
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
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from prometheus_client import Counter, Histogram, make_asgi_app

# ---------- 1. 结构化日志 ----------
def setup_logging(service_name: str = "agent-api"):
    """配置 loguru 输出结构化 JSON 日志，并注入 trace_id。"""
    logger.remove()
    log_format = (
        '{{"timestamp":"{time:YYYY-MM-DDTHH:mm:ss.SSSZ}",'
        '"level":"{level}",'
        '"service":"' + service_name + '",'
        '"trace_id":"{extra[trace_id]}",'
        '"span_id":"{extra[span_id]}",'
        '"message":"{message}",'
        '"extra":{extra[payload]}}}'
    )
    logger.add(
        os.getenv("LOG_FILE", "/var/log/agent/app.log"),
        format=log_format,
        rotation="100 MB",
        retention="14 days",
        level=os.getenv("LOG_LEVEL", "INFO"),
        serialize=False,
    )
    # 给所有日志注入默认 trace_id（无追踪上下文时为 "-"）
    logger.configure(extra={"trace_id": "-", "span_id": "-", "payload": "{}"})


class TraceContextFilter:
    """把当前 OTel span 的 trace_id 注入到 loguru 日志。"""
    @staticmethod
    def bind_logger():
        span = trace.get_current_span()
        ctx = span.get_span_context() if span else None
        if ctx and ctx.is_valid:
            return logger.bind(
                trace_id=f"{ctx.trace_id:032x}",
                span_id=f"{ctx.span_id:016x}",
            )
        return logger.bind(trace_id="-", span_id="-")


# ---------- 2. OpenTelemetry 追踪 ----------
def setup_tracing(service_name: str = "agent-api"):
    """初始化 OTel，上报到 OTel Collector（Jaeger/Tempo 后端）。"""
    resource = Resource.create({"service.name": service_name})
    provider = TracerProvider(resource=resource)
    exporter = OTLPSpanExporter(
        endpoint=os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://localhost:4317")
    )
    provider.add_span_processor(BatchSpanProcessor(exporter))
    trace.set_tracer_provider(provider)
    return trace.get_tracer(__name__)


# ---------- 3. Prometheus 指标 ----------
REQUESTS = Counter(
    "agent_requests_total", "Agent 请求总数", ["endpoint", "status"]
)
LATENCY = Histogram(
    "agent_request_duration_seconds", "Agent 请求延迟", ["endpoint"],
    buckets=(0.1, 0.5, 1, 2, 5, 10, 30, 60)
)
LLM_TOKENS = Counter(
    "agent_llm_tokens_total", "LLM Token 消耗", ["model", "type"]
)

下面是接入三件套的 FastAPI 应用：

# app.py —— 接入可观测性的 Agent 接口
import time
from fastapi import FastAPI, Request
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from prometheus_client import make_asgi_app
from observability import (
    setup_logging, setup_tracing, TraceContextFilter,
    REQUESTS, LATENCY, LLM_TOKENS,
)
from opentelemetry import trace

# 初始化三支柱
setup_logging("agent-api")
tracer = setup_tracing("agent-api")

app = FastAPI()
# 自动为每个 HTTP 请求创建根 Span
FastAPIInstrumentor.instrument_app(app)
# 挂载 Prometheus 指标端点 /metrics
app.mount("/metrics", make_asgi_app())


@app.middleware("http")
async def observability_middleware(request: Request, call_next):
    """记录每个请求的指标与日志。"""
    start = time.time()
    status_code = 500
    try:
        response = await call_next(request)
        status_code = response.status_code
        return response
    finally:
        duration = time.time() - start
        endpoint = request.url.path
        REQUESTS.labels(endpoint=endpoint, status=status_code).inc()
        LATENCY.labels(endpoint=endpoint).observe(duration)
        log = TraceContextFilter.bind_logger()
        log.info(
            "request completed",
            extra={"payload": (
                f'{{"endpoint":"{endpoint}",'
                f'"status":{status_code},'
                f'"duration_ms":{duration*1000:.0f}}}'
            )},
        )


@app.get("/chat")
async def chat(q: str):
    """Agent 问答接口：检索 + LLM 调用，每步都建子 Span。"""
    with tracer.start_as_current_span("retrieve_docs") as span:
        span.set_attribute("retrieval.query_length", len(q))
        docs = _retrieve(q)
        span.set_attribute("retrieval.doc_count", len(docs))
        TraceContextFilter.bind_logger().info(
            "retrieval done", extra={"payload": f'{{"docs":{len(docs)}}}'}
        )

    with tracer.start_as_current_span("llm_call") as span:
        span.set_attribute("llm.model", "gpt-4o-mini")
        answer, tokens = _call_llm(q, docs)
        span.set_attribute("llm.tokens", tokens)
        LLM_TOKENS.labels(model="gpt-4o-mini", type="total").inc(tokens)
        TraceContextFilter.bind_logger().info(
            "llm call done", extra={"payload": f'{{"tokens":{tokens}}}'}
        )

    return {"answer": answer, "docs": len(docs)}


# ---- 模拟依赖 ----
def _retrieve(query: str) -> list[str]:
    time.sleep(0.2)  # 模拟向量检索
    return ["doc1 内容", "doc2 内容"]

def _call_llm(query: str, docs: list[str]) -> tuple[str, int]:
    time.sleep(0.8)  # 模拟 LLM 推理
    return f"基于 {len(docs)} 篇文档回答: ...", 350


if __name__ == "__main__":
    import uvicorn
    uvicorn.run(app, host="0.0.0.0", port=8000)

启动后访问 http://localhost:8000/chat?q=什么是RAG，在 Jaeger 中能看到这样一棵 Trace 树：

GET /chat                    (root span, ~1000ms)
├── retrieve_docs            (200ms, attr: doc_count=2)
└── llm_call                 (800ms, attr: model=gpt-4o-mini, tokens=350)

一眼看出 LLM 调用占了 80% 耗时。同时每条日志都带上了相同的 trace_id，在 Loki 中用该 ID 一搜，就能看到这次请求的完整日志链路。

配套的 Prometheus 告警规则示例：

# alerts.yml —— Prometheus 告警规则
groups:
  - name: agent_alerts
    rules:
      - alert: HighErrorRate
        expr: |
          sum(rate(agent_requests_total{status=~"5.."}[5m]))
          / sum(rate(agent_requests_total[5m])) > 0.05
        for: 2m
        labels:
          severity: P1
        annotations:
          summary: "Agent 错误率超 5%"
          description: "近 5 分钟错误率 {{ $value | humanizePercentage }}，请检查 LLM 上游状态"

      - alert: HighLatencyP95
        expr: |
          histogram_quantile(0.95,
            rate(agent_request_duration_seconds_bucket[5m])) > 5
        for: 5m
        labels:
          severity: P2
        annotations:
          summary: "Agent P95 延迟超 5 秒"

      - alert: LLMTokenSpike
        expr: |
          rate(agent_llm_tokens_total[1h]) > 100000
        for: 10m
        labels:
          severity: P2
        annotations:
          summary: "LLM Token 消耗激增，可能存在滥用或缓存失效"

企业案例¶

案例 1：Agent 系统监控¶

某 AI 客服厂商上线后经常收到"偶发变慢"反馈，但无法复现。接入 OpenTelemetry 后，在 Jaeger 中按"延迟 > 5 秒"筛选 Trace，发现慢请求都卡在 vector_search Span，进一步查日志发现是向量库某个分片负载不均。修复分片策略后 P95 延迟从 8 秒降到 1.5 秒。

团队还建立了"Token 消耗看板"：按租户、模型维度统计 Token，一旦某租户 Token 激增（可能是缓存失效或恶意调用），Grafana 立即告警。一次因 Prompt 模板变更导致缓存 key 失效的事故，正是靠这个看板在 10 分钟内发现并回滚。

案例 2：用 trace_id 串联全链路日志¶

一家金融 Agent 平台把 trace_id 注入到所有日志、消息、甚至写入数据库的任务记录。排查"某笔分析报告结果异常"时，只需用报告 ID 查到对应的 trace_id，就能在 Loki 中一次搜出从 API 入口、检索、LLM 调用、工具执行到结果落库的全部日志，配合 Jaeger 的 Span 树，定位耗时从"翻几小时日志"缩短到"5 分钟看图"。

常见问题¶

Q1：日志该打到文件还是直接推到日志中心？ 推荐打到本地文件 + 采集器（Promtail/Filebeat）推送，解耦应用与日志系统。直接推日志中心会增加应用依赖，网络抖动时可能丢日志或拖慢主流程。

Q2：OpenTelemetry 性能开销大吗？ 合理使用下很小。BatchSpanProcessor 异步批量上报，不影响请求路径。注意：Span 属性别塞大对象（如完整 Prompt），只记关键属性；高频接口的 Span 可通过采样率降低上报量。

Q3：追踪一定要跨服务才有意义吗？ 不一定。单服务内的多步操作（检索→LLM→工具）用 Span 树同样有价值，能看清每步耗时。跨服务时通过 SpanContext 传递串联，价值更大。

Q4：告警太多怎么办？ 三步治理：按 SLO 重设阈值（去掉单点告警）、聚合窗口（5 分钟内同类告警合并）、设抑制规则（父告警触发时抑制子告警）。目标是"每天收到告警不超过个位数，且每条都该处理"。

Q5：loguru 和标准 logging 怎么选？ loguru 开箱即用、API 简洁、支持结构化与轮转，适合中小项目与 Agent 服务。大型组织若已用标准 logging + dictConfig 体系，保持一致即可。两者都可输出 JSON 供采集。

面试题¶

1. 可观测性三支柱分别解决什么问题？ 答：日志记录离散事件细节（"发生了什么"），指标提供聚合时序数据（"整体趋势"），追踪还原单次请求的调用链路（"这一请求怎么走的"）。三者通过 trace_id 串联，形成"发现异常→定位链路→查看细节"的排查闭环。

2. 为什么强调结构化日志？ 答：纯文本日志难以被机器解析与检索。结构化日志（JSON）让每个字段可索引、可聚合、可关联，便于用 trace_id 跨服务串联、按字段过滤统计，是日志能被有效利用的前提。

3. Prometheus 的 pull 模式有什么优劣？ 答：优点是服务无状态、不依赖推送、自带服务发现、目标失效时采集失败可见。缺点是不适合短时任务（进程结束前 Prometheus 来不及拉），需用 Pushgateway 中转。Agent 系统的长驻服务适合 pull。

4. OpenTelemetry 的 SpanContext 如何跨服务传递？ 答：通过 HTTP/gRPC header（W3C TraceContext 规范，如 traceparent header）注入与提取。上游在发请求前把当前 SpanContext 写入 header，下游收到后提取作为父 Span，从而串联成跨服务 Trace 树。

5. 如何设计一个不刷屏的告警体系？ 答：基于 SLO 而非单点阈值、分级（P0/P1/P2）、聚合窗口合并同类、抑制规则避免父子重复、每条告警必有 runbook、定期复盘告警质量并清理噪声。

练习题¶

在示例代码基础上，给 _call_llm 增加异常捕获：LLM 调用失败时记 ERROR 日志（带 trace_id）、Span 标记为 ERROR 状态、错误计数指标 +1，并重新抛出异常让上层处理。
配置一个 Grafana 仪表盘，包含四个面板：QPS、P95 延迟、错误率、Token 消耗，并按租户维度筛选。
用 Jaeger 查一次慢请求（延迟 > 3 秒）的 Trace，截图其 Span 树，分析哪一步是瓶颈，并写一段优化建议。
思考题：如果 Agent 用了流式响应（SSE），如何在追踪中记录"首 token 延迟"与"总 token 数"两个关键指标？

小结¶

本章建立了 Agent 系统可观测性的完整认知：日志、指标、追踪三支柱分工协同——指标发现异常、追踪定位链路、日志看清细节，三者靠 trace_id 串联。我们用 loguru 输出结构化日志、用 Prometheus 采集黄金指标、用 OpenTelemetry 为请求打上 Span 树，并给出了告警规则示例。核心要点：可观测性是生产系统的生命线，没有它，你在黑暗中排障；有了它，故障定位从"翻日志几小时"变成"看图几分钟"。至此，第 11 卷的系统设计三件套——高并发缓存、异步队列、可观测性——已全部就位，下一卷我们将进入部署运维，把这些设计真正跑在生产环境上。

第3章 日志与监控、链路追踪¶