通过 pprof 调试 Filebeat

因为 Filebeat 是用 Go 语言实现的，而 Go 语言本身的基础库里面就包含 pprof 这个功能极其强大的性能分析工具，因此，在 7.x 版本中，Beats 家族的工具，都提供了以下参数，方便用户在出现问题的时候，对应用进行调试：

1
2
3
4
5
6
7
8
--cpuprofile FILE
    Writes CPU profile data to the specified file. This option is useful for troubleshooting Filebeat.
-h, --help
    Shows help for the run command.
--httpprof [HOST]:PORT
    Starts an http server for profiling. This option is useful for troubleshooting and profiling Filebeat.
--memprofile FILE
    Writes memory profile data to the specified output file. This option is useful for troubleshooting Filebeat.

比如：

1
2
3
4
# 生成 CPU 使用的分析文件
filebeat -e --cpuprofile cpu.ppof
# 开放 web 端口，进行远程调试
filebeat -e -httpprof localhost:6060

-httpprof 远程调试

这里先简单介绍一下远程调试，当我们按照上面的命令，在 6060 端口提供了远程调试界面后，我们可以通过浏览器访问：

简介说明：

  • allocs：所有过去内存分配的样本
  • block：导致同步原语阻塞的堆栈跟踪
  • cmdline：当前程序的命令行调用
  • goroutine：所有当前 goroutine（协程）的堆栈跟踪
  • heap：活动对象的内存分配示例。您可以指定 gc GET 参数以在获取堆样本之前运行 GC
  • mutex：争用互斥锁持有者的堆栈跟踪
  • profile：CPU 分析文件。您可以在 GET 参数中指定持续时间。获取配置文件后，使用 go tool pprof 命令调查配置文件
  • threadcreate：导致创建新操作系统线程的堆栈跟踪
  • trace：当前程序的执行轨迹。您可以在 GET 参数中指定持续时间。获取跟踪文件后，使用 go tool trace 命令调查跟踪

因此，如果这里要对 CPU 使用率进行调试，我们需要通过访问 debug/pprof/profile 路径，以获取分析文件，比如：http://localhost:6060/debug/pprof/profile?seconds=33

远程连接

当然，你也可以通过在你的本地电脑上安装 Go，然后通过 go tool 远程连接 pprof：

1
go tool pprof http://localhost:6060/debug/pprof/profile

top 命令

连接之后，你可以通过 top 命令，查看消耗内存最多的几个实例：

1
2
3
4
5
6
7
8
9
10
11
12
Type: cpu
Time: Feb 22, 2022 at 11:09am (CST)
Duration: 30.01s, Total samples = 10ms (0.033%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 10ms, 100% of 10ms total
      flat  flat%   sum%        cum   cum%
      10ms   100%   100%       10ms   100%  runtime.pthread_cond_timedwait_relative_np
         0     0%   100%       10ms   100%  runtime.notetsleep_internal
         0     0%   100%       10ms   100%  runtime.notetsleepg
         0     0%   100%       10ms   100%  runtime.semasleep
         0     0%   100%       10ms   100%  runtime.timerproc

web 命令

输入 web 命令，会生成堆栈调用关系的 svg 图，在这个 svg 图中，你可以结合 top 命令一起查看，在图中，展现的是调用关系栈，你可以看到这个类是怎么被实例化的：

最直观的是，实例所处的长方形面积越大，代表占用的 CPU 时间越多。

CPU Profile

在介绍 CPU 概要文件的生成方法之前，我们先来简单了解一下 CPU 主频。CPU 的主频，即 CPU 内核工作的时钟频率（CPU Clock Speed）。CPU 的主频的基本单位是赫兹（Hz），但更多的是以兆赫兹（MHz）或吉赫兹（GHz）为单位。时钟频率的倒数即为时钟周期。时钟周期的基本单位为秒（s），但更多的是以毫秒（ms）、微妙（us）或纳秒（ns）为单位。在一个时钟周期内，CPU 执行一条运算指令。也就是说，在 1000 Hz 的 CPU 主频下，每 1 毫秒可以执行一条 CPU 运算指令。在 1 MHz 的 CPU 主频下，每 1 微妙可以执行一条 CPU 运算指令。而在 1 GHz 的 CPU 主频下，每 1 纳秒可以执行一条 CPU 运算指令。

在默认情况下，Go 语言的运行时系统会以 100 Hz 的频率对 CPU 使用情况进行取样。也就是说每秒取样 100 次，即每 10 毫秒会取样一次。为什么使用这个频率呢？因为 100 Hz 既足够产生有用的数据，又不至于让系统产生停顿。并且 100 这个数上也很容易做换算，比如把总取样计数换算为每秒的取样数。实际上，这里所说的对 CPU 使用情况的取样就是对当前的 Goroutine 的堆栈上的程序计数器的取样。由此，我们就可以从样本记录中分析出哪些代码是计算时间最长或者说最耗 CPU 资源的部分了。

像上图，Duration: 30.01s, Total samples = 10ms (0.033%)，表示在 30.01 秒中，一共采用了 10ms 的 CPU profile 信息，占总体时间的 0.033%。而这 10ms 中，所有的时间都花费在了 runtime.pthread_cond_timedwait_relative_np 函数上。

再来看一个复杂点的图：

现在，我们把视线放在主要的图形上。此图形由矩形和有向线段组成。在此图形的大多数矩形中都包含三行信息。第一行是函数的名字。第二行包含了该函数的本地取样计数（在括号左边的数字）及其在取样总数中所占的比例（在括号内的百分比）。第三行则包含了该函数的累积取样计数（括号左边的数字）及其在取样总数中所占的比例（在括号内的百分比）。

首先，读者需要搞清楚两个相似但不相同的概念，即：本地取样计数和累积取样计数。本地取样计数的含义是当前函数在取样中直接出现的次数。累积取样计数的含义是当前函数以及当前函数直接或间接调用的函数在取样中直接出现的次数。所以，存在这样一种场景：对于一个函数来说，它的本地取样计数是 0，因为它没有在取样中直接出现过。但是，由于它直接或间接调用的函数频繁地直接出现在取样中，所以这个函数的累积取样计数却会很高。

我们以上图中的函数 main.main 为例。由于 main.main 函数在所有取样中都没有直接出现过，所以它的本地取样计数为 0。但又由于它是命令源码文件中的入口函数，程序中其他的函数都直接或间接地被它调用。所以，它的累积取样计数是所有函数中最高的，达到了 22。

注意，不论是本地取样计数还是累积取样计数都没有把函数对自身的调用计算在内。函数对自身的调用又被称为递归调用。

speedscope UI

当然，我们还可以用更加直观的方式分析，这里给大家推荐一个网站，https://www.speedscope.app/。我们只需要将 go tool 生成的 profile 文件，上传到网站上：

就可以通过各种图形化的界面进行分析：

具体帮助可以查看：https://github.com/jlfwong/speedscope#views

实战

这是在客户那里遇到的一个问题，Filebeat 在负载很低（只监控了一个文件的情况下），CPU 使用率居然接近 100%：

从配置文件上看，都是合理配置，可以排除因为配置不当而导致的可能：

因此，就需要通过 profile 进行分析了，通过添加 --cpuprofile 参数，获取 Profile：

1
./filebeat run --cpuprofile /tmp/cpu.ppof -e

用 go tool pprof cpu.ppof 命令进行分析，top 后得到如下信息：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
File: filebeat
Build ID: af0436205acb301a20a095f9d67add9ca5ccdcb7
Type: cpu
Time: Feb 21, 2022 at 7:23pm (CST)
Duration: 1.06mins, Total samples = 49.42s (77.60%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web
(pprof) top
Showing nodes accounting for 23340ms, 47.23% of 49420ms total
Dropped 420 nodes (cum <= 247.10ms)
Showing top 10 nodes out of 204
      flat  flat%   sum%        cum   cum%
   11240ms 22.74% 22.74%    11530ms 23.33%  syscall.Syscall
    2220ms  4.49% 27.24%     9010ms 18.23%  runtime.mallocgc
    1830ms  3.70% 30.94%     2800ms  5.67%  runtime.scanobject
    1400ms  2.83% 33.77%     2650ms  5.36%  bufio.(*Writer).Write
    1340ms  2.71% 36.48%     1340ms  2.71%  runtime.memmove
    1140ms  2.31% 38.79%     3790ms  7.67%  github.com/elastic/beats/v7/libbeat/statestore/backend/memlog.(*countWriter).Write
    1110ms  2.25% 41.04%     4040ms  8.17%  github.com/elastic/go-structform/json.(*Visitor).OnString
    1050ms  2.12% 43.16%     1310ms  2.65%  runtime.heapBitsSetType
    1050ms  2.12% 45.29%     1050ms  2.12%  runtime.memclrNoHeapPointers
     960ms  1.94% 47.23%      960ms  1.94%  runtime.nextFreeFast (inline)

1 分钟内，采样了将近 50 秒，信息足够。从 top 上看（以本地取样计数为顺序列出函数或方法及相关信息，默认情况下 top 命令会列出前 10 项内容），以上 10 个函数被调用的次数，占用 CPU 的时钟最多，但它们之间的关系不甚明晰。

通过 web 查看：

可以看到，方形越大，代表在本地取样计数的值越大，而颜色越深（由灰到红），则代表累积取样计数的值越大。

这里，我们可以看到明显的一条红色的调用链路。

还是不够直观。我们通过 speedscope UI 进行分析，可以看到，这几个函数被反复顺序调用：

因此，可以确定，CPU 的调用与这几个函数有很强的联系。

将这几个函数，放到 GitHub 上的 Beats 项目中搜索，发现堆栈与这个问题类似：https://github.com/elastic/beats/issues/20705

再对比日志：

确认是同一个问题。可以通过清除 data 目录多余 json 文件解决。

总结

因为 Filebeat 是用 Go 语言实现的，只要善用 Go 语言本身性能分析工具，我们就能自己发现很多性能问题的根本原因。

另外，尽量升级到 Fleet GA 的 Elastic Stack 版本，并使用 Elastic Agent，这样，我们就可以通过 Fleet 来远程更新和升级 Elastic Agent，避免手动维护 Filebeat 的麻烦。