第18章日志与链路追踪

第18章：日志与链路追踪：ELK栈搭建、分布式追踪、日志聚合、故障定位

做市商系统跑起来之后，最怕什么？

不是行情暴跌，也不是策略亏钱。而是系统出了故障，你翻遍所有服务器，却找不到一条有用的日志。

我经历过这种绝望。有一次凌晨三点，我们的报价引擎突然停止响应。我登录到四台机器上，用 grep 和 tail -f 来回切换，折腾了一个多小时才定位到问题——一个线程池满了。那晚我就下定决心，必须把日志和链路追踪搞利索。

核心观点：日志不是写给机器看的，是写给「未来出故障时的你」看的。ELK + 分布式追踪，就是给未来的你装上一台时光机。

18.1 日志体系设计：从混乱到有序

做市商系统的日志，我一般分成三个层次：

业务日志：记录每一笔报价、成交、撤单。这是审计和复盘的基础。
系统日志：记录内存、CPU、网络延迟、线程池状态。这是性能分析的依据。
异常日志：记录所有未捕获的异常、超时、重试次数。这是故障定位的第一现场。

我个人习惯，每个微服务实例的日志文件按天滚动，保留30天。文件名格式统一为：{服务名}_{日期}.log。别小看这个命名规范，我在项目中见过有人用 log1.log、log2.log 这种名字，找起来简直要命。

18.2 ELK栈搭建：让日志会说话

ELK 栈，说白了就是三个组件：Elasticsearch（存）、Logstash（收）、Kibana（看）。

我推荐用 Filebeat 替代 Logstash 做日志采集端。为什么？因为 Logstash 吃内存太狠了，而 Filebeat 轻量得多。Filebeat 把日志发到 Kafka 或 Redis，再由 Logstash 消费并写入 ES。

架构图如下：

嗯，这里要注意：ES 的索引模板一定要提前设计好。我见过有人直接把日志丢进 ES，结果字符串字段被当成 text 类型，导致聚合查询慢得像蜗牛。

一个典型的索引模板配置：

{
  "index_patterns": ["logs-*"],
  "settings": {
    "number_of_shards": 3,
    "number_of_replicas": 1,
    "refresh_interval": "30s"
  },
  "mappings": {
    "properties": {
      "@timestamp": { "type": "date" },
      "service_name": { "type": "keyword" },
      "level": { "type": "keyword" },
      "message": { "type": "text" },
      "trace_id": { "type": "keyword" },
      "duration_ms": { "type": "integer" }
    }
  }
}

避坑指南：我曾经把 refresh_interval 设成 1s，结果 ES 集群 CPU 直接飙到 90%。对于日志场景，30s 刷新一次完全够用。实时性要求高的业务日志，单独建索引。

18.3 分布式追踪：把散落的珍珠串起来

做市商系统里，一个报价请求可能要经过网关、路由、定价引擎、风控、交易执行五个服务。如果每个服务各自打日志，你根本没法把一次完整的请求串起来。

分布式追踪就是干这个的。我用的方案是 Jaeger + OpenTelemetry。

核心思路很简单：每个请求进来时，生成一个全局唯一的 trace_id，然后在每个服务调用时，把这个 ID 透传下去。所有日志都带上这个 ID，你就能在 Kibana 里搜出一次请求的全貌。

代码实现上，我习惯在 gRPC 的拦截器里做这件事：

// 客户端拦截器：注入 trace_id
func ClientInterceptor() grpc.UnaryClientInterceptor {
    return func(ctx context.Context, method string, req, reply interface{},
        cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
        
        traceID := extractTraceID(ctx)
        if traceID == "" {
            traceID = uuid.New().String()
        }
        ctx = metadata.AppendToOutgoingContext(ctx, "x-trace-id", traceID)
        return invoker(ctx, method, req, reply, cc, opts...)
    }
}

// 服务端拦截器：提取 trace_id
func ServerInterceptor() grpc.UnaryServerInterceptor {
    return func(ctx context.Context, req interface{},
        info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
        
        md, ok := metadata.FromIncomingContext(ctx)
        if ok {
            traceIDs := md.Get("x-trace-id")
            if len(traceIDs) > 0 {
                ctx = context.WithValue(ctx, "trace_id", traceIDs[0])
            }
        }
        return handler(ctx, req)
    }
}

你想想看，如果没有这个 trace_id，你要怎么排查一个报价延迟了 200ms 的问题？你得去四个服务里翻日志，还得靠时间戳去猜哪个调用对应哪个请求。有了 trace_id，一条 grep "trace_id=abc123" *.log 就搞定了。

18.4 日志聚合：从海量数据中捞针

做市商系统一天能产生几十 GB 的日志。怎么从里面快速找到有用的信息？

我的做法是「分层聚合」：

第一层：实时告警。用 ElastAlert 或自建规则引擎，对 ERROR 级别日志做实时匹配。比如「连续 3 次报价超时」就触发告警。
第二层：聚合分析。在 Kibana 里建一些常用的聚合查询。比如按服务名统计错误率、按 trace_id 统计请求耗时分布。
第三层：离线归档。超过 7 天的日志，压缩后存到冷存储。ES 里只保留最近 7 天的热数据。

这里有个小技巧：日志里一定要带上 duration_ms 字段。这样你就能在 Kibana 里画出每个服务的响应时间趋势图。我靠这个图发现过好几次性能瓶颈——某个服务的响应时间在下午 2 点到 4 点会突然飙升，后来发现是那个时段有定时任务在抢 CPU。

18.5 故障定位：从分钟级到秒级

有了 ELK 和分布式追踪，故障定位就变成了一套标准流程：

步骤	操作	工具
1	查看告警面板，确认故障范围和影响	Grafana + Prometheus
2	在 Kibana 中搜索对应时间段的 ERROR 日志	Kibana Discover
3	提取异常请求的 trace_id	Kibana
4	在 Jaeger 中查看该 trace 的完整调用链	Jaeger UI
5	定位到耗时最长或报错的服务	Jaeger 火焰图
6	查看该服务的详细日志，找到根因	Kibana

这套流程走下来，大部分问题能在 5 分钟内定位。我曾经用这套方法，在 3 分钟内找到了一个因为 Redis 连接池耗尽导致的报价延迟问题。要是放在以前，光翻日志就得半小时。

注意：分布式追踪不是银弹。它只能帮你定位「哪个服务慢」或「哪个调用失败」，但「为什么慢」还得靠业务日志和代码分析。另外，采样率要控制好，100% 采样在高并发场景下会拖垮性能。我一般设 10% 的采样率，出问题时再临时调到 100%。

18.6 实战经验总结

最后分享几个我踩过的坑：

日志不要打太多。我曾经见过一个同事在循环里打 DEBUG 日志，结果日志文件一天涨了 200GB。日志是给人看的，不是给硬盘看的。
统一日志格式。所有服务用同一个日志库，输出 JSON 格式。这样 Logstash 解析起来最省事。我见过有人用纯文本日志，解析规则写了一百多行，还经常出错。
ES 集群要预留余量。磁盘使用率超过 80% 时，ES 会自动把索引设为只读。做市商系统日志量增长很快，我建议预留 50% 的磁盘余量。
链路追踪要覆盖所有入口。不只是 gRPC 调用，还包括 Kafka 消息、定时任务、WebSocket 连接。我漏过 Kafka 消息的追踪，结果排查问题时发现中间有一段是黑盒。

日志和链路追踪，说白了就是给系统装上一套「黑匣子」。平时你可能觉得它可有可无，但一旦出了故障，它就是你的救命稻草。别等到凌晨三点才想起来搭 ELK，那时候你连觉都睡不好。

无相订单流研究社微信Lucian808555

📚 课程目录