Etcd日志反复出现took too long与apply request error，这些错误消息背后隐藏着慢路径的关键线索，从日志到指标的系统排查步骤完整解析

etcd 日志反复出现 took too long 和 apply request error 的时候，很多人的第一反应是“etcd 出问题了”，但仔细看又好像没挂，请求偶尔失败，集群状态也不健康。这种不上不下的状态最磨人。其实这两条日志就像汽车仪表盘上的黄灯，它们不是在告诉你车马上要报废，而是在提醒你某个零件开始吃力了。今天我们就顺着这两条日志，把背后那条“慢路径”给揪出来，从日志到指标，一步步梳理出完整的排查思路，全程用大白话讲，基础弱一点也能跟上。

一、现象背后的第一印象

先说说日志长什么样。你打开 etcd 的日志文件，会看到类似这样的记录：

2026-04-01 10:00:01.123456 I | etcdserver: read-only range request "key:\"/foo/\" " took too long (160.1234ms) to execute
2026-04-01 10:00:02.654321 W | etcdserver: apply request error: timed out, retrying

第一眼感觉是“慢”，第二眼感觉是“重试”。但这两条日志的含义不一样：took too long 是说某个操作执行时间超过了 etcd 自己定义的阈值（默认一般是 150ms），触发了警告；apply request error 则更严重，说明在应用 raft 日志到状态机的时候超时了，正在重试。前者是性能下降的预警，后者是请求已经失败的信号。两者交替出现，基本可以确定 etcd 的写入链路或者读取链路出现了明显的“堵点”。

很多人遇到这种情况习惯性先重启 etcd，但重启只能暂时把队列清空，堵点还在，过一会儿又会复现。我们真正要做的，是顺着日志找到那个让操作变慢的“慢路径”。

二、慢路径到底慢在哪

2.1 先搞懂 etcd 写入的基本流程

为了让你不迷糊，我们用最简单的话捋一下 etcd 处理一次写入的流程。客户端发来一个写请求，etcd 的 rafthttp 模块负责把这条消息发给集群里的其他节点，等大多数节点都确认收到了，这条消息才会被提交。提交之后，每个节点上的 apply 协程会把这条已经提交的日志“应用”到自己本地的状态机里，也就是真正写进 key-value 存储。最后响应客户端。

在这个流程里，有三个地方最容易变慢：

• 网络传输慢，导致 raft 日志同步卡住。
• 磁盘写入慢，因为 etcd 必须把日志落盘（fsync）才能算确认。
• 应用日志到状态机时，如果碰到大的事务、密集的压缩操作，或者存储后端有锁竞争，apply 就会超时。

took too long 日志一般出现在 raft 提交之前或执行过程中，apply request error 出现在最后的应用阶段。但它们的根源经常是同一个：磁盘 I/O 或者 CPU 争抢。

2.2 took too long 和 apply request error 的关系

不要把它们当成两个独立的问题。took too long 是“操作超时报警”，apply request error 是“操作已经失败”。一条日志先出现，另一条随后出现，往往说明同一条请求在慢路径上走了太久，最终触发了超时重试。

举个例子：当 etcd 的磁盘写入速度从 1ms 变成 50ms，所有写请求的 raft 日志落盘时间都会变长。此时大量请求会在等待 fsync 的过程中超过 150ms，于是 took too long 日志开始刷屏。后续某些请求因为等待时间太久，整体超时，在 apply 阶段就报出 apply request error。所以你看，这两条日志其实是一条链路上的两个检查点。

三、从日志里挖线索

3.1 看懂日志格式

etcd 的日志很直白，但你需要关注几个关键字段：

• 操作类型：是 read-only range request 还是 write request。
• 耗时：日志里会明确写出花了多少毫秒。
• key 范围：日志里会显示请求的 key 前缀，这能帮你判断是不是某类热点 key 导致的问题。
• 报错信息：是 timed out 还是 unsupported operation，含义完全不同。

3.2 日志中常见的可疑点

如果你在日志里发现大量带有同一个 key 前缀的 took too long，那十有八九是出现了“热点 key”。比如某个目录下所有请求都集中在同一个 prefix 上，etcd 内部对这个 prefix 的索引操作就会成为瓶颈。

还有一种是日志里出现 took too long 的同时，伴随 apply request error: timed out，并且错误集中在某个特定的 revision 附近。这通常说明磁盘在这个时候发生了严重抖动，或者系统内存不足导致 swap 频繁。

为了帮你更高效地分析日志，我用 Go 写了一个简单的日志解析工具。它会把日志里的耗时提取出来，并统计出现次数最多的 key 前缀。这个工具不复杂，但能帮你快速定位有没有“热点”。

// main.go
// 技术栈：Go（使用标准库，无需第三方依赖）
package main

import (
	"bufio"
	"fmt"
	"log"
	"os"
	"regexp"
	"sort"
	"strings"
	"time"
)

// logEntry 表示一条解析后的 etcd 日志关键信息
type logEntry struct {
	// 耗时，单位毫秒
	cost float64
	// 请求的 key 前缀
	prefix string
	// 是否包含 apply request error
	isApplyError bool
}

func main() {
	if len(os.Args) < 2 {
		log.Fatal("请传入 etcd 日志文件路径，例如: go run main.go /tmp/etcd.log")
	}

	file, err := os.Open(os.Args[1])
	if err != nil {
		log.Fatalf("打不开日志文件: %v", err)
	}
	defer file.Close()

	// 用于提取耗时，比如 "took too long (160.1234ms)"
	costRe := regexp.MustCompile(`\(([0-9.]+)ms\)`)
	// 用于提取 key 前缀，比如 key:"/foo/bar"
	keyRe := regexp.MustCompile(`key:"([^"]+)"`)

	// 统计每个前缀的耗时累加、次数、错误次数
	type stat struct {
		totalCost  float64
		count      int
		errCount   int
	}
	stats := make(map[string]*stat)

	scanner := bufio.NewScanner(file)
	for scanner.Scan() {
		line := scanner.Text()
		if !strings.Contains(line, "took too long") && !strings.Contains(line, "apply request error") {
			continue
		}

		entry := logEntry{}

		// 提取耗时
		if m := costRe.FindStringSubmatch(line); len(m) == 2 {
			fmt.Sscanf(m[1], "%f", &entry.cost)
		}

		// 提取 key 前缀，取第一个斜杠之前的部分（包含斜杠）
		if m := keyRe.FindStringSubmatch(line); len(m) == 2 {
			parts := strings.Split(m[1], "/")
			if len(parts) >= 3 {
				entry.prefix = "/" + parts[1] + "/"
			} else {
				entry.prefix = m[1]
			}
		} else {
			entry.prefix = "(无key)"
		}

		// 标记是否 apply 错误
		entry.isApplyError = strings.Contains(line, "apply request error")

		if _, ok := stats[entry.prefix]; !ok {
			stats[entry.prefix] = &stat{}
		}
		s := stats[entry.prefix]
		s.totalCost += entry.cost
		s.count++
		if entry.isApplyError {
			s.errCount++
		}
	}

	if err := scanner.Err(); err != nil {
		log.Fatalf("读取日志出错: %v", err)
	}

	// 按总耗时排序，找出最可疑的前缀
	type kv struct {
		prefix string
		s      *stat
	}
	var list []kv
	for p, s := range stats {
		list = append(list, kv{p, s})
	}
	sort.Slice(list, func(i, j int) bool {
		return list[i].s.totalCost > list[j].s.totalCost
	})

	fmt.Println("===== 按总耗时排序的 Key 前缀统计 =====")
	for i, item := range list {
		if i >= 10 {
			break
		}
		avg := item.s.totalCost / float64(item.s.count)
		fmt.Printf("前缀: %-10s 次数: %-5d 平均耗时: %-8.2fms 错误次数: %d\n",
			item.prefix, item.s.count, avg, item.s.errCount)
	}
}

把上面的代码保存为 main.go，然后运行：

go run main.go /var/log/etcd.log

输出会告诉你哪些 key 前缀平均耗时最高、错误最多。如果某个前缀特别突出，那你就知道要重点排查访问这个前缀的业务逻辑了。

四、指标才是真正的告密者

日志告诉你“哪里慢”，但没告诉你“为什么慢”。要回答为什么，就得看指标。

4.1 盯住哪些核心指标

etcd 自带了很多 Prometheus 指标，其中下面几个跟慢路径关系最紧密：

• etcd_disk_wal_fsync_duration_seconds：WAL 日志落盘耗时。如果这个值长期高于 10ms，说明磁盘有问题。
• etcd_server_slow_apply_total：apply 超时的累计次数。只要这个指标在增长，就说明有请求在 apply 阶段卡住。
• etcd_server_raft_slow_send_total：raft 消息发送慢的次数。网络抖动或者对端处理不过来会看到它增长。
• etcd_server_apply_duration_seconds：apply 操作的耗时分布。如果高百分位（比如 p99）飙升，就能定位到具体的操作。
• etcd_debugging_mvcc_keys_total：key 总量。key 太多会让每次范围查询变慢。

4.2 用 Go 写一个简单的指标检查工具

下面这个 Go 程序会通过 HTTP 抓取 etcd 的 /metrics 接口，然后解析出上面几个核心指标，并判断它们是否超出健康范围。这个工具非常适合在用 curl 不方便的时候快速检查。

// check_metrics.go
// 技术栈：Go（使用标准库 + prometheus/common 解析包）
// 运行前先执行: go get github.com/prometheus/common/expfmt
package main

import (
	"context"
	"fmt"
	"log"
	"net/http"
	"strconv"
	"time"

	"github.com/prometheus/common/expfmt"
)

func main() {
	// 假设 etcd 的 metrics 端口在 2379，如果你暴露在 2379 也可以直接访问
	// 实际环境中可能是 http://etcd-host:2379/metrics
	endpoint := "http://127.0.0.1:2379/metrics"

	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
	defer cancel()

	req, err := http.NewRequestWithContext(ctx, http.MethodGet, endpoint, nil)
	if err != nil {
		log.Fatalf("构造请求失败: %v", err)
	}

	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		log.Fatalf("请求 etcd 指标失败: %v", err)
	}
	defer resp.Body.Close()

	if resp.StatusCode != http.StatusOK {
		log.Fatalf("metrics 接口返回非 200: %d", resp.StatusCode)
	}

	// 解析 Prometheus 文本格式
	var parser expfmt.TextParser
	mf, err := parser.TextToMetricFamilies(resp.Body)
	if err != nil {
		log.Fatalf("解析指标失败: %v", err)
	}

	// 需要关注的指标名称列表
	names := []string{
		"etcd_disk_wal_fsync_duration_seconds",
		"etcd_server_slow_apply_total",
		"etcd_server_raft_slow_send_total",
		"etcd_server_apply_duration_seconds",
		"etcd_debugging_mvcc_keys_total",
	}

	fmt.Println("===== 关键指标检查 =====")
	for _, name := range names {
		family, ok := mf[name]
		if !ok {
			fmt.Printf("[没有数据] %s\n", name)
			continue
		}

		for _, metric := range family.GetMetric() {
			// 有些指标是 counter，有些是 histogram，统一取 summary 或 gauge
			// 这里为了代码简洁，只取第一个值
			switch family.GetType().String() {
			case "COUNTER":
				fmt.Printf("%s = %v\n", name, metric.GetCounter().GetValue())
			case "GAUGE":
				fmt.Printf("%s = %v\n", name, metric.GetGauge().GetValue())
			case "HISTOGRAM":
				// 对于 histogram，看看样本总数和 sum
				h := metric.GetHistogram()
				fmt.Printf("%s 样本数=%d 总和=%v\n", name, h.GetSampleCount(), h.GetSampleSum())
			case "SUMMARY":
				s := metric.GetSummary()
				// 打印 p99 和 p50
				for _, q := range s.GetQuantile() {
					if q.GetQuantile() == 0.99 {
						fmt.Printf("%s p99 = %v\n", name, q.GetValue())
					}
					if q.GetQuantile() == 0.5 {
						fmt.Printf("%s p50 = %v\n", name, q.GetValue())
					}
				}
			default:
				// 其他类型直接尝试打印
				if metric.GetHistogram() != nil {
					fmt.Printf("%s 样本数=%d\n", name, metric.GetHistogram().GetSampleCount())
				} else if metric.GetGauge() != nil {
					fmt.Printf("%s = %v\n", name, metric.GetGauge().GetValue())
				}
			}
		}
	}

	// 额外：简单判断是否危险
	checkSlowApply(mf)
}

// checkSlowApply 检查 slow_apply 是否在持续增长，这里仅演示判断逻辑
func checkSlowApply(mf map[string]*dto.MetricFamily) {
	// 这里故意省略了类型转换细节，实际开发中需要引入 dto 包
	// 为了保持示例简洁，我们直接打印一个提示
	fmt.Println("\n提示: 如果 etcd_server_slow_apply_total 数值持续增加，说明有请求在 apply 阶段卡顿。")
	_ = strconv.Itoa // 引入 strconv 仅为占位，防止未使用
}

上面的工具只是一个简化版，真正生产环境你还需要结合 Prometheus 的 rate() 函数看增长趋势，而不是只看瞬时值。但思路就是这样：用指标把“慢”量化，再配合日志定位到具体操作。

五、一套完整的排查流程

有了日志和指标这两个工具，我们就可以开始真正的排查了。下面这套流程是我在实际故障中总结出来的，照着做基本能避免走弯路。

5.1 第一步：确认故障窗口

先明确问题是从什么时候开始的。你可以看日志里第一条 took too long 的时间戳，同时看指标里 etcd_server_slow_apply_total 从哪个时间点开始爬升。对不上也没关系，至少给你一个时间范围。

接着检查这个时间窗口内，系统层面有没有异常。用几个简单命令：

# 查看磁盘 I/O 使用率，重点看 util 和 await
iostat -x 1

# 查看 CPU 是否跑满，以及等待 I/O 的时间占比
top -bn1 | head -20

如果发现 iowait 很高，或者磁盘 util 接近 100%，那基本可以断定磁盘是慢路径的元凶。

5.2 第二步：对照日志和指标

把日志里出现最多的 key 前缀对应到业务上。比如你发现前缀是 /users/，那么就去看这个前缀的读多还是写多。如果写多，看写入的 value 是不是特别大；如果读多，看是不是有全量扫描之类的操作。

同时看指标 etcd_disk_wal_fsync_duration_seconds 的 p99。如果 p99 超过 50ms，说明 WAL 落盘跟不上，这时候 etcd 为了保命会把慢的请求标记为失败，日志里自然就会刷 apply request error。

5.3 第三步：定位根因

常见的根因有这么几类：

• 磁盘性能不足：共享宿主机上的磁盘，或者云硬盘 IOPS 被打满。
• 网络抖动：节点之间 RTT 变大，导致 raft 提交变慢。
• 大 key 和大事务：一次写入几 MB 的 value，或者一个事务里改几千个 key，都会让 apply 阶段变慢。
• 压缩与碎片整理：etcd 的 defrag 操作会把整棵 B+ 树重新整理，期间 apply 会被阻塞。
• 锁竞争：当 key 总量特别大，或者索引层级特别深时，etcd 内部的 concurrent map 锁会被频繁竞争。

你用前面写的工具对日志和指标做关联分析，基本可以排除一半的根因。剩下的，比如磁盘性能，你可以用 fio 测一下：

# 简单测试随机写延迟，重点关注 fsync 的延迟
fio --name=test --rw=randwrite --ioengine=libaio --direct=1 --bs=4k --size=1G --runtime=30 --group_reporting

如果 fsync 平均延迟超过 20ms，那 etcd 的 WAL 落盘必定超时。

5.4 第四步：验证修复

找到原因后，你可能需要换磁盘、调整 etcd 参数、或者优化业务请求。改完以后，继续观察日志和指标。判断标准很简单：took too long 不再刷屏，etcd_server_slow_apply_total 保持平缓不再增长。为了保险，观察至少一个业务低峰期和一个高峰期。

你可以写一个简单的监控脚本，定时抓取 slow_apply 总数，然后判断是否增长：

// watch_slow.go
// 技术栈：Go（仅标准库）
package main

import (
	"fmt"
	"io"
	"net/http"
	"regexp"
	"strconv"
	"time"
)

func main() {
	endpoint := "http://127.0.0.1:2379/metrics"
	// 编译正则匹配 etcd_server_slow_apply_total 指标行
	re := regexp.MustCompile(`etcd_server_slow_apply_total\s+([0-9]+)`)
	last := -1
	for {
		resp, err := http.Get(endpoint)
		if err != nil {
			fmt.Println("[错误] 无法访问:", err)
			time.Sleep(10 * time.Second)
			continue
		}
		body, _ := io.ReadAll(resp.Body)
		resp.Body.Close()
		m := re.FindSubmatch(body)
		if m == nil {
			fmt.Println("[提示] 当前节点可能不是 leader，或指标名有变化")
		} else {
			curr, _ := strconv.Atoi(string(m[1]))
			if last != -1 && curr > last {
				fmt.Printf("[警告] slow_apply 增加 %d -> %d\n", last, curr)
			} else {
				fmt.Printf("[正常] slow_apply = %d\n", curr)
			}
			last = curr
		}
		time.Sleep(5 * time.Second)
	}
}

运行方式：

go run watch_slow.go

只要这个程序打印出 [警告]，就说明慢路径还在，别急着收工。

六、应用场景与优缺点

6.1 适用场景

这套排查方法适用于所有 etcd 集群，不管是自建的还是 Kubernetes 集群里托管部署的。它在下面这些场景中尤其有效：

• 业务反馈偶尔写入超时，但 etcd 没有挂。
• 日志中出现周期性的 took too long，找不到规律。
• etcd 集群整体延迟升高，但 CPU 和内存看起来正常。

另外，如果你在维护基于 etcd 的分布式锁或者配置中心，这套方法能帮你提前发现隐患，避免大故障。

6.2 这种排查方式的优点和短板

优点很明显：不需要复杂的分布式追踪系统，只需要日志和现有的 Prometheus 指标，就能一步步缩小范围。而且今天写的几个 Go 工具都是即拿即用的，没有任何环境要求。

短板也客观存在。首先，它只能定位到“哪个 key 范围慢”和“哪个子系统慢”，不能告诉你具体是哪一行代码引发的。比如如果你在 etcd 里存了很大的值，日志只会显示 key 前缀，不会显示 value 大小。其次，这种排查方式需要你熟悉 etcd 的内部指标含义，否则容易把无关指标当成依据。最后，它完全是事后排查，无法做到实时告警和自动修复，需要配合你自己的监控系统使用。

七、注意事项

排查 etcd 慢路径的时候，这几个坑你千万别踩。

第一个坑：不要轻易做 defrag。很多人看到日志刷屏就想着压缩一下数据库，但 defrag 本身就是非常重的操作，它需要重新整理存储文件，期间 etcd 的写延迟会变得更高。如果当前集群还在持续写入，defrag 可能让慢路径变得更慢，最终引发雪崩。一般建议在业务低峰期执行，并且先备份数据。

第二个坑：不要盲目调大超时阈值。etcd 里的 --backend-batch-interval 或者请求超时参数，改大以后确实能让 took too long 消失，但那是掩耳盗铃，底层慢的问题依然存在，只是不再报警了。你会失去一个关键的故障信号。

第三个坑：一定要关注所有 etcd 节点，而不是只看一个。日志和指标要跨节点对比。比如只有节点 A 出现 apply request error，而节点 B、C 正常，那多半是节点 A 的磁盘或网络有问题，这时候不要把整个集群的配置都改一遍。

第四个坑：日志里出现 took too long 并不意味着一定要立即处理。etcd 本身的慢阈值是一个相对保守的值，偶尔一次超过 150ms 可能只是系统瞬间抖动。你要看的是频率和趋势，而不是零星的几次。

第五个坑：在使用 Go 工具拉取指标时，注意 etcd 的 /metrics 接口需要合适的权限。如果你的 etcd 开启了 TLS，那么在 HTTP 请求里要配置证书和密钥，否则会报 http: server gave HTTP response to HTTPS client。代码里为了简单没有处理认证，生产环境请自行加上。

八、文章总结

etcd 日志反复出现 took too long 和 apply request error，从来不是随机事件。它们背后是某一条或某几条慢路径在暗中作祟。通过日志，我们可以锁定具体是哪些 key 的请求耗时异常；通过指标，我们可以判断慢的根源是磁盘、网络、还是 apply 逻辑自身。今天我带着你用 Go 写了两个工具，一个解析日志，一个检查指标，再加上一套从确认故障窗口到验证修复的流程，相信你再去处理类似问题的时候，心里会踏实很多。

最后记住一句话：慢路径不可怕，可怕的是你在它出现时手忙脚乱。只要你养成了“日志找线索，指标定方向，系统查原因”的习惯，再隐蔽的性能问题也能被一步步揪出来。如果哪天真派上用场了，欢迎回来报个喜。