追踪链路缺失导致问题定位困难？LlamaIndex可观测性接入与日志增强

一、先聊聊问题：链路丢了，排查就像大海捞针

你有没有遇到过这种场景：辛辛苦苦把基于大模型的应用搭起来了，用到 LlamaIndex 做了文档问答。结果线上用户说“机器人回答好慢”或者“直接报错了”。你赶紧跑去看日志，结果日志里只有一行“Request failed”或者“timeout”，没有上下文，没有到底哪一步出了错。你问同事，同事也一头雾水。没办法，只能把日志级别调到 DEBUG，重新跑一遍，祈祷能够复现。就算复现了，也只知道某个环节挂了，但不知道是“文档加载”的问题，还是“检索”的问题，或者是“调用大模型”的问题。这种感觉就像在一个黑暗的房间里找一个掉在地上的针，你只知道针肯定在，但不知道在哪儿。

这种痛苦的根源，就是应用缺少一套完整、清晰的追踪链路。我们在开发的时候，代码是一条直线走下来的，但到了线上，多线程、异步、并发一起来，调用关系变成了一张网。一旦某个节点超时，你根本不知道是哪个节点。可观测性要解决的就是这个问题。今天咱们就用 LlamaIndex 来聊一聊，怎么把这条链路补上，让排查问题变得像看体检报告一样清清楚楚。

二、可观测性到底是啥？为什么这么重要？

这里说的可观测性，不是让你去装一套复杂的监控系统。它的核心就三样东西：日志、指标、追踪。咱们用大白话解释一下。

日志，就好比你把每天做的事情写进日记里。几点几分发生了什么，记一笔。指标呢，就是你给自己定的 KPI，比如今天跑了多少公里，心跳多少。追踪，则是给每一件任务一个编号，然后记录从开始到结束，每一步都经过了哪些地方，每个地方花了多长时间。

对于一个基于 LlamaIndex 的应用来说，追踪尤其重要。因为一次问答请求，内部可能经历了好几个阶段：先要把用户的问题处理一下，然后去向量库里面找相关的文档，再把这些文档拼接到上下文里，最后调用大模型生成回答。这一串流程，只要任何一个环节出问题，整个请求就失败。如果没有追踪，你只能知道“失败了”，但不知道“在哪一步失败的”。

好消息是，LlamaIndex 本身就已经预留了“可观测性”的插槽。你可以不用改一行业务逻辑，就能看到内部的执行过程。下面我们就来动手搞一遍。

三、LlamaIndex 天生就有“可插拔”的观测接口

LlamaIndex 里面有一个叫做回调管理器（CallbackManager）的东西，它就像一个总机，可以让我们在关键节点上挂上“监听器”。当程序运行到加载文档、检索、构造提示词、调用模型这些地方时，监听器就会被触发，把当时的参数和耗时告诉你。

3.1 准备一个最简单的 RAG 示例

我们先用一个最简单的 RAG（检索增强生成）应用来做演示。技术栈统一使用 Python 和 LlamaIndex 0.10.x。假设你已经有 Python 环境，只需要安装 llama-index 和 openai 相关的包。我们用一个本地文档做知识库，然后问它一个问题。

# 技术栈：Python + LlamaIndex 0.10.x

from llama_index.core import VectorStoreIndex, SimpleDirectoryReader
from llama_index.core import Settings
from llama_index.llms.openai import OpenAI

# 配置大模型，这里用 OpenAI 的接口
Settings.llm = OpenAI(model="gpt-3.5-turbo", temperature=0)

# 读取当前目录下的 product.txt 文件（比如一份产品说明书）
documents = SimpleDirectoryReader(input_files=["product.txt"]).load_data()

# 建立索引（这一步会把文档拆成小块，并生成向量）
index = VectorStoreIndex.from_documents(documents)

# 创建一个查询引擎，专门用来回答用户问题
query_engine = index.as_query_engine()

# 提出问题
response = query_engine.query("这个产品支持无线充电吗？")
print(response)

这段代码很简单，创建索引然后查询。但这里面到底做了什么？我们看不到。如果查询很慢，我们也不知道慢在哪里。接下来我们加上可观测性。

3.2 接上追踪：让每一步都留下脚印

LlamaIndex 提供了回调机制。我们可以自己写一个处理器，把事件开始和结束的瞬间都打出来。这样就能看到一次请求内部到底走了哪些流程。

# 技术栈：Python + LlamaIndex 0.10.x

from llama_index.core.callbacks import CallbackManager, CBEventType
from llama_index.core.callbacks.base_handler import BaseCallbackHandler
from llama_index.core import Settings

class PrintHandler(BaseCallbackHandler):
    """自定义回调处理器，把每个事件的开始和结束打印出来。"""

    def on_event_start(self, event_type: CBEventType, payload: dict, event_id: str, **kwargs):
        # 事件开始时打印类型和事件ID
        print(f"[开始] {event_type.value} 事件ID: {event_id}")
        # 打印关键参数，但不要把太长的文本直接堆出来
        if payload:
            for key, value in payload.items():
                if isinstance(value, str) and len(value) > 50:
                    value = value[:50] + "..."
                print(f"      参数: {key} = {value}")

    def on_event_end(self, event_type: CBEventType, payload: dict, event_id: str, **kwargs):
        # 事件结束时打印结束标记
        print(f"[结束] {event_type.value} 事件ID: {event_id}")

# 创建一个回调管理器，并挂上我们的处理器
callback_manager = CallbackManager([PrintHandler()])
Settings.callback_manager = callback_manager

# 重新执行查询，观察控制台输出
response = query_engine.query("这个产品支持无线充电吗？")
print("答案是：", response)

运行之后，你会看到屏幕上刷出来一串事件，比如 RETRIEVE（检索）、SYNTHESIZE（合成回答）等等。每个事件都有不同的 ID，但你还是看不出它们之间的前后关系。而且这里也没记录耗时，我们还需要再增强一下。

3.3 给追踪加上耗时和层级

为了更直观地看到哪一步慢，我们可以把事件耗时记下来，并且用缩进来表示嵌套关系。下面这个自定义处理器，维护了一个事件栈，可以打印出类似“调用树”的效果。

# 技术栈：Python + LlamaIndex 0.10.x

import time
from collections import defaultdict
from llama_index.core.callbacks import CallbackManager, CBEventType
from llama_index.core.callbacks.base_handler import BaseCallbackHandler
from llama_index.core import Settings

class TracingHandler(BaseCallbackHandler):
    """一个简单的追踪处理器，记录每个事件的耗时，并用缩进展示调用关系。"""

    def __init__(self):
        # 用字典保存每个事件开始的时间戳
        self.start_times = {}
        # 维护一个事件ID栈，用来计算缩进层级
        self.event_stack = []

    def on_event_start(self, event_type: CBEventType, payload: dict, event_id: str, **kwargs):
        # 记录开始时间
        self.start_times[event_id] = time.time()
        # 把当前事件压入栈，栈的深度就是缩进量
        self.event_stack.append((event_id, event_type))
        indent = "  " * len(self.event_stack)
        print(f"{indent}开始 {event_type.value}")

    def on_event_end(self, event_type: CBEventType, payload: dict, event_id: str, **kwargs):
        # 计算耗时
        duration = time.time() - self.start_times.pop(event_id, time.time())
        # 找到栈中对应的位置，把事件弹出去
        for i in range(len(self.event_stack) - 1, -1, -1):
            if self.event_stack[i][0] == event_id:
                self.event_stack.pop(i)
                break
        indent = "  " * len(self.event_stack)
        print(f"{indent}结束 {event_type.value}，耗时 {duration * 1000:.2f} 毫秒")

# 使用这个追踪处理器
Settings.callback_manager = CallbackManager([TracingHandler()])
response = query_engine.query("这个产品支持无线充电吗？")
print("回答：", response)

这样一来，控制台会输出类似下面这样的结果（具体事件可能因版本略有差异）：

开始 RETRIEVE
  开始 EMBEDDING
  结束 EMBEDDING，耗时 120.00 毫秒
结束 RETRIEVE，耗时 350.00 毫秒
开始 SYNTHESIZE
  开始 LLM
  结束 LLM，耗时 1200.00 毫秒
结束 SYNTHESIZE，耗时 1250.00 毫秒

是不是清楚多了？如果用户说慢，你一眼就能看出时间花在哪个环节。

3.4 更省事的办法：接入 OpenTelemetry

自己写处理器虽然灵活，但生产环境里往往有更多要求，比如把追踪数据统一送到监控平台。这时候可以接入 OpenTelemetry。这是一个业界标准的可观测性框架，你可以把它理解成一个“通用的仪表盘接口”。LlamaIndex 官方直接支持，几行代码就能打开。

# 技术栈：Python + LlamaIndex 0.10.x

from llama_index.core import set_global_handler

# 启用 OpenTelemetry 追踪，并把数据发送到本地 collector
set_global_handler("otlp_tracing", endpoint="http://localhost:4317")

接下来你只需要在本地跑一个 OpenTelemetry Collector，再用 Jaeger 或者 Zipkin 这类工具把追踪数据可视化显示出来。这样你就能通过网页看到一次请求的完整调用链，包括每个阶段的耗时、输入输出等等。对于团队规模较大、需要统一监控的场景，这是更专业的选择。

四、日志增强：光有追踪还不够，把上下文喂给排查的人

追踪给了我们一条“流水线”，但流水线上每个环节到底干了什么，还需要日志来补充。比如检索到了哪几个文档？每个文档的得分是多少？最终答案是基于哪一段内容生成的？这些信息对排查问题非常重要。

4.1 在关键位置打日志

我们可以在查询引擎外面包一层，记录用户问题、检索中间结果、最终回答。这里我们用 Python 的 logging 模块，并给每次请求生成一个 request_id，方便串联日志。

# 技术栈：Python + LlamaIndex 0.10.x

import logging
import uuid
import time

# 设置日志格式，并预留 request_id 字段
logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s | %(levelname)s | %(name)s | request_id=%(request_id)s | %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)

logger = logging.getLogger("rag_app")

class QueryLogger:
    """在 LlamaIndex 查询引擎外面包一层，用于记录请求日志。"""

    def query(self, question: str):
        # 为这次请求生成一个短 ID
        request_id = str(uuid.uuid4())[:8]

        # extra 参数里放进 request_id，这样日志里自动带上
        extra = {"request_id": request_id}

        logger.info("收到用户问题: %s", question, extra=extra)
        start = time.time()

        # 调用 LlamaIndex 的查询引擎
        response = query_engine.query(question)

        # 遍历检索到的节点，打印得分和内容片段（内容截断，防止刷屏）
        for i, node in enumerate(response.source_nodes):
            snippet = node.node.get_text()[:80].replace("\n", " ")
            logger.info("检索第%d个节点，得分: %.2f，内容片段: %s",
                        i + 1,
                        node.score,
                        snippet,
                        extra=extra)

        elapsed = time.time() - start
        logger.info("最终回答: %s", str(response)[:120], extra=extra)
        logger.info("本次请求耗时: %.3f 秒", elapsed, extra=extra)

        return str(response)

# 使用带日志的查询器
ql = QueryLogger()
answer = ql.query("这个产品支持无线充电吗？")
print("回答：", answer)

有了这样的日志，线上排查就变得简单了。只要用户报错时把 request_id 给你，你拿这个 ID 去日志系统里一搜，就能看到这次请求完整的时间线：问题是什么，检索到了哪些文档，每个文档的得分是多少，最终回答是什么，耗时多少。一眼就能判断出是检索不准，还是模型生成有问题。

4.2 把日志和追踪关联起来

如果你同时用了 OpenTelemetry 之类的追踪系统，可以把日志里的 request_id 和追踪里的 trace_id 对应起来。比如在回调里拿到当前 trace_id，然后一起打到日志里。这样以后通过日志跳转到追踪面板，或者从追踪面板跳转到对应的日志，都很方便。虽然实现细节依赖具体平台，但核心思路就是“在日志里多记一个全局唯一的 ID”。

五、应用场景：什么时候最需要这套东西？

你可能会想：我这个应用还小，要不要这么麻烦？我的建议是，只要你的应用要给别人用，或者将来要迭代，就值得花半天时间接一下。尤其是下面几种场景。

第一，生产环境排障。用户报错，你需要快速定位是不是某一次升级导致的。有追踪和日志，你直接按时间线看就好。第二，评估回答质量。当用户说“你回答得不对”时，你能看到检索出来的文档是不是相关，模型是不是被带偏了。第三，性能优化。一次请求耗时 3 秒，你用追踪一看，发现 2.5 秒都花在检索上，那你就知道该优化向量库了。第四，团队协作时扯皮。运维说“应用没问题”，后端说“模型太慢”，你把追踪数据甩出来，谁的问题一目了然。

六、技术优缺点：别盲目上，先看适不适合

好处很明显。能让你看到系统内部的执行顺序，摸清性能瓶颈；能记录完整的上下文，减少“凭感觉”排查；能自动关联一次请求的所有信息，不用再人工去拼时间线。这些都是实打实的好处。

但也要注意成本。开启追踪会带来额外的性能开销，虽然通常很小，但并发量特别大的时候会有影响。第二个是存储成本，追踪数据、日志数据都会占用磁盘和网络，需要定期清理或归档。第三个是学习成本，要理解回调、处理器、追踪 ID 这些概念，刚开始可能会觉得复杂。不过和晚上熬夜排查问题比起来，这点成本太值了。

七、注意事项：坑和避坑指南

第一，不要记录敏感信息。日志和追踪里可能会包含用户上传的文档内容或者个人信息。一旦日志泄露，麻烦就大了。所以在记录节点文本的时候，最好打码或者截断，甚至不记正文，只记文件名和位置。

第二，控制日志量。如果每一条检索到的文档片段都完整打出来，日志量会爆炸。我们可以在生产环境只记录摘要和关键字段，比如只记录文档的文件名、页码和得分。

第三，异步环境下要小心上下文传递。如果你用了异步查询，需要确保 request_id 能正确地在不同协程间传递。否则你可能发现日志里的 request_id 是乱的，反而更难排查。解决方法是把 request_id 放在上下文中，或者使用专门的日志框架去传递全局变量。

第四，版本兼容性。LlamaIndex 迭代很快，回调接口偶尔会变。升级版本之后，记得重新测试一遍追踪代码，别让观测模块成了新的“错误源”。最好把追踪相关的代码独立成一个模块，方便做兼容性修复。

第五，不要把所有的宝都押在外部服务上。如果你用 OpenTelemetry Collector，它挂了怎么办？要设置好数据传输的超时，并且保证主流程不受影响。你可以把追踪数据当成一个“锦上添花”的东西，而不是“非有不可”的依赖。这样即使观测系统出了问题，你的业务还是能正常跑。

八、总结：把“黑盒”变成“透明盒”

咱们从“问题定位困难”开始，聊到可观测性的三个核心，再到 LlamaIndex 的 Callback 机制，最后用日志增强把上下文补全。这一套组合拳下来，你的 LlamaIndex 应用就不再是一个黑盒了。哪怕出了问题，你也可以像老中医一样“望闻问切”，通过追踪和日志快速判断是哪个器官（模块）在闹脾气。

生活就是这样，早点花时间把工具准备好，后面就能少熬夜。希望这篇文章能帮你在 LlamaIndex 的路线上走得踏实一些。如果你现在正在为排查问题头疼，不妨现在就去接一套追踪和日志，相信你一定会感谢自己。