当 etcd 服务器 CPU 飙高时,最快的定位方法就是直接剖析运行中的进程,并解读它的 Go 级别 CPU 火焰图。本教程中,OpenResty XRay 会分析一个占用了超过 70% CPU 核心资源的未经修改的 etcd 二进制程序——无需改动任何代码,也无需重启——并精准定位最热的 Go 代码路径:gRPC 请求处理(processUnaryRPC)、键值存储的 range 和 put 处理函数,以及 Go 运行时的栈增长(runtime.newstack)。

本教程演示使用 OpenResty XRay 分析 Go 的 etcd 服务器内部是如何耗费 CPU 时间的。我将展示其中最耗 CPU 的 Go 代码路径。OpenResty XRay 会自动分析 Go(golang)语言级别的 CPU 火焰图。

问题症状:etcd 占用超过 70% 的 CPU 核心

运行 top 命令可以看到,etcd 进程占用了超过 70% 的 CPU 核心资源(这里是 74.3%):

top 命令显示 etcd 进程占用了 74.3% 的 CPU 核心

ps 命令确认这是一个标准的 etcd 二进制程序(/usr/local/bin/etcd),以普通的集群参数启动——没有自定义构建、没有任何剖析插桩,也没有任何形式的改动:

ps 命令显示未经修改的 /usr/local/bin/etcd 二进制程序及其命令行

使用引导式分析定位 etcd 最热的 Go 代码路径

借助 OpenResty XRay,我们可以实时分析这个未经修改的运行中进程。“Guided Analysis”(引导式分析)向导会依次引导我们选择诊断类型、分析目标和应用类型。我们选择 High CPU usage(高 CPU 使用率)作为要诊断的问题:

OpenResty XRay 引导式分析的问题类型菜单,其中包含 High CPU usage 选项

接着,我们选择运行中的 etcd 进程作为分析目标。OpenResty XRay 将其识别为一个 Go 应用(PID 3638889,约 76% CPU),我们保持默认的 Go 语言级别和默认的 300 秒最大运行时间,然后开始分析:

在 OpenResty XRay 中选择运行中的 etcd Go 进程作为分析目标

经过几轮采样后,OpenResty XRay 生成了一份报告。它按 CPU 时间对最热的 Go 代码路径进行排名,同时列出 read 和 write 系统调用各消耗了多少 CPU:

OpenResty XRay 的 CPU 报告,按 CPU 时间对 etcd 最热的 Go 代码路径排名,processUnaryRPC 以 17.6% 居首

这个是占用 CPU 时间最多的 Go 级别代码路径,占了 17.6% 的 CPU 时间:

报告中排名第一的最热 Go 代码路径,占 17.6% 的 CPU 时间

这个 processUnaryRPC 是 Go 的 gRPC 库中的一个函数。它负责处理最简单的 gRPC 消息——单个请求对应单个响应:

代码路径中高亮显示的 processUnaryRPC 函数,来自 Go 的 gRPC 库

它的上级调用函数是 handleStream

代码路径显示 handleStream 是 processUnaryRPC 的上级调用函数

点击 “More” 查看细节信息:

点击 More 按钮查看这条代码路径的细节信息

解读 Go CPU 火焰图

上面的代码路径就是从这个 Go 级别 CPU 火焰图中自动推导出来的。在火焰图中,每个栈帧的宽度与它所占的 CPU 时间成正比:

OpenResty XRay 为运行中的 etcd 进程采样得到的 Go 级别 CPU 时间火焰图

点击这个图标放大火焰图:

点击放大图标放大 Go CPU 火焰图

继续放大:

继续放大火焰图中最热的调用栈

_KV_Range_Handler 函数可以获取键值数据库中一定范围内的 key:

火焰图放大到 processUnaryRPC 之下的 etcd _KV_Range_Handler 函数

_KV_Put_Handler 函数将给定的 key 放入键值数据库中:

火焰图中的 etcd _KV_Put_Handler 函数,负责将 key 写入键值存储

Range 函数用于按范围查询存储在 etcd 中的键值数据:

火焰图中 etcd 的 Range 函数,用于按范围查询键值数据

它会调用 runtime.newobject 创建大量的 golang GC 对象:

火焰图显示 Range 查询之下的 runtime.newobject 分配大量 Go GC 对象

runtime.newstack 函数在 etcd 写入数据时有较高的 CPU 开销。该函数是 Go 语言运行时的一个内部函数,它为新的 goroutine 创建一个新的运行时栈:

火焰图显示 etcd 写入路径上的 runtime.newstack 栈创建开销

下面是对当前问题更详细的解释和建议,例如减少网络上传输的数据、使用连接池以及调优 gRPC 配置:

OpenResty XRay 对 processUnaryRPC 代码路径的解释以及优化建议

它提到了函数 processUnaryRPC

解释文字中提到的 processUnaryRPC 函数

也提到了它是处理一元 RPC 的:

解释文字说明 processUnaryRPC 负责处理一元 RPC

跳转到源码行

让我们回到刚才的代码路径上来。把鼠标放在第一个函数的绿色框上:

鼠标悬停在代码路径第一个函数的绿色框上

可以看到这个函数的源文件名。在提示框中还可以看到 server.go 文件的完整路径:

提示框显示 processUnaryRPC 的源文件 grpc server.go 的完整路径

这行源码的行号是 1024:

提示框显示该行源码的行号是 1024

点击这个图标,复制这个函数完整的 Go 源文件路径:

点击复制图标复制完整的 Go 源文件路径

使用 find 命令来查找源文件:

在终端中使用 find 命令查找 Go 源文件

粘贴我们刚刚复制的文件路径:

在 find 命令中粘贴刚刚复制的源文件路径

复制完整的文件路径。使用 vim 编辑器,查看这个文件里的 golang 代码。您可以使用任何您喜欢的编辑器:

使用 vim 编辑器打开 grpc server.go 源文件

正如 OpenResty XRay 建议的那样跳转到第 1024 行:

vim 中跳转到 grpc server.go 的第 1024 行

函数 md.Handler 会根据 gRPC 消息的不同类型,选择合适的消息处理程序来调用。我们之前看到的 _KV_Range_Handler_KV_Put_Handler 就是 md.Handler 回调函数的两个实例:

源码第 1024 行的 md.Handler 调用,分发到各个 gRPC 消息处理函数

在状态栏中可以看到这行代码也确实在 processUnaryRPC 函数中,正如之前报告中提到的:

vim 状态栏确认第 1024 行代码位于 processUnaryRPC 函数中

其他热点代码路径

CPU 占用第二热的 Go 代码路径,使用了大约 12% 的 CPU 资源:

报告中排名第二的最热 Go 代码路径,占约 12% 的 CPU 时间

这个函数的作用是把数据写入到网络 socket 里:

代码路径显示把响应数据写入网络 socket 的函数

这里执行的是 write 这个系统调用:

代码路径底部执行的 write 系统调用

这个函数通过 HTTP/2 协议将响应数据发送到网络 socket:

代码路径中通过 HTTP/2 协议发送响应数据的函数

排名第三的最热 Go 代码路径占用了大约 11% 的 CPU 时间:

报告中排名第三的最热 Go 代码路径,占约 11% 的 CPU 时间

这里的 runtime.mcall 函数主要负责调度执行 goroutine:

代码路径中负责调度 goroutine 的 runtime.mcall 函数

这是 CPU 占用第四热的 Go 代码路径,占了约 10.5% 的 CPU 时间:

报告中排名第四的最热 Go 代码路径,占约 10.5% 的 CPU 时间

这个函数的功能是记录每一次一元 gRPC 请求的调用。为了节约 CPU 资源,我们可以选择不做这样的日志记录:

代码路径中记录每次一元 gRPC 调用日志的函数

etcd CPU 全自动监控与报告

除了按需运行的引导式分析,OpenResty XRay 还能自动监控在线进程,并在 “Insights” 页面生成以日和周为周期的报告。对于这个 etcd 实例,日报显示 CPU 使用率平均为 51.33%(峰值达 164%),其中 write 系统调用和 Go GC 对象分配位列 CPU 消耗最多的项目之中:

OpenResty XRay 的 Insights 日报,展示 etcd 的平均和峰值 CPU 使用率以及消耗 CPU 最多的项目

由于这些报告是自动生成的,您并不需要亲自去运行引导式分析——引导式分析在应用开发和演示场景下最为有用。

常见问题

为什么我的 etcd 服务器占用这么多 CPU?

在本例中,etcd 的大部分 CPU 时间都花在了处理 gRPC 请求上。最热的单条 Go 代码路径是 Go gRPC 库中的 processUnaryRPC(占 17.6% 的 CPU 时间),它会分发到 etcd 的 _KV_Range_Handler_KV_Put_Handler——分别负责从键值存储中读取某一范围的 key 以及向其中写入 key。通过 HTTP/2 发送响应数据,以及 Go 运行时的工作(runtime.newobjectruntime.newstack 以及经由 runtime.mcall 的 goroutine 调度)占据了其余的大部分。同样的方法适用于任何 CPU 使用率偏高的 Go 程序;参见如何定位最热的 Go 代码路径

如何在不修改、不重启 etcd 的情况下剖析它的 CPU 使用情况?

OpenResty XRay 直接分析运行中的、未经修改的 etcd 进程——无需改动代码、无需重新构建、也无需重启。它的 “Guided Analysis”(引导式分析)功能会对运行中的进程进行采样,并自动推导出 Go 级别的 CPU 火焰图和最热的代码路径。

etcd 在高 CPU 下最热的代码路径有哪些?

对于本次负载,最热的几条路径是:(1) processUnaryRPC 处理一元 gRPC 调用,进而进入 KV 的 range 和 put 处理函数(17.6%);(2) 通过 HTTP/2 将响应数据写入网络 socket(11.7%);(3) runtime.mcall 调度 goroutine(11.1%);(4) 记录每一次一元 gRPC 调用的日志(10.5%)——为节约 CPU 时间,您可以考虑跳过这类日志。

关于 OpenResty XRay

OpenResty XRay 是一个动态追踪产品,它可以自动分析运行中的应用程序,以解决性能问题、行为问题和安全漏洞,并提供可行的建议。在底层实现上,OpenResty XRay 由我们的 Y 语言驱动,可以在不同环境下支持多种不同的运行时,如 Stap+、eBPF+、GDB 和 ODB。

关于作者

章亦春是开源 OpenResty® 项目创始人兼 OpenResty Inc. 公司 CEO 和创始人。

章亦春(Github ID: agentzh),生于中国江苏,现定居美国湾区。他是中国早期开源技术和文化的倡导者和领军人物,曾供职于多家国际知名的高科技企业,如 Cloudflare、雅虎、阿里巴巴, 是 “边缘计算“、”动态追踪 “和 “机器编程 “的先驱,拥有超过 22 年的编程及 16 年的开源经验。作为拥有超过 4000 万全球域名用户的开源项目的领导者。他基于其 OpenResty® 开源项目打造的高科技企业 OpenResty Inc. 位于美国硅谷中心。其主打的两个产品 OpenResty XRay(利用动态追踪技术的非侵入式的故障剖析和排除工具)和 OpenResty Edge(最适合微服务和分布式流量的全能型网关软件),广受全球众多上市及大型企业青睐。在 OpenResty 以外,章亦春为多个开源项目贡献了累计超过百万行代码,其中包括,Linux 内核、Nginx、LuaJITGDBSystemTapLLVM、Perl 等,并编写过 60 多个开源软件库。

关注我们

如果您喜欢本文,欢迎关注我们 OpenResty Inc. 公司的博客网站 。也欢迎扫码关注我们的微信公众号:

我们的微信公众号

翻译

我们提供了英文版原文和中译版(本文)。我们也欢迎读者提供其他语言的翻译版本,只要是全文翻译不带省略,我们都将会考虑采用,非常感谢!