Elastic Stack最佳实践系列：filebeat CPU使用率过高分析

在上一篇文章记一次filebeat内存泄漏问题分析及调优中，我们分享了如何限制和分析filebeat的内存使用情况。在本篇中，我们将继续探索我们使用filebeat或者是beats其他组件时，可能遇到的问题。除了内存之外，CPU的使用率是我们关心的另外一个问题，一个辅助的信息采集工具，永远不应该影响业务进程的正常工作，因此，当filebeat出现可能的CPU使用率过高问题时，也需要我们尽快分析和解决。

通过pprof调试filebeat

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

--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.

比如：

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

-httpprof 远程调试

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

image.png

简介说明：

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。

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

top 命令

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

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命令一起查看，在图中，展现的是调用关系栈，你可以看到这个类是怎么被实例化的：

image.png

最直观的是，实例所处的长方形面积越大，代表占用的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-3.jpeg

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

首先，读者需要搞清楚两个相似但不相同的概念，即：本地取样计数和累积取样计数。本地取样计数的含义是当前函数在取样中直接出现的次数。累积取样计数的含义是当前函数以及当前函数直接或间接调用的函数在取样中直接出现的次数。所以，存在这样一种场景：对于一个函数来说，它的本地取样计数是0。因为它没有在取样中直接出现过。但是，由于它直接或间接调用的函数频繁的直接出现在取样中，所以这个函数的累积取样计数却会很高。我们以上图中的函数mian.main为例。由于main.main函数在所有取样中都没有直接出现过，所以它的本地取样计数为0。但又由于它是命令源码文件中的入口函数，程序中其他的函数都直接或间接的被它调用。所以，它的累积取样计数是所有函数中最高的，达到了22。注意，不论是本地取样计数还是累积取样计数都没有把函数对自身的调用计算在内。函数对自身的调用又被称为递归调用。

speedscope UI

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

image.png

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

image.png

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

实战

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

image.png

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

image.png

因此，就需要通过profile进行分析了，通过添加--cpuprofile参数，获取Profile: ./filebeat run --cpuprofile /tmp/cpu.ppof -e

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

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) 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，看

image.png

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

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

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

image.png

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

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

WechatIMG77.jpg

再对比日志:

image.png

image.png

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

总结

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

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