perf (Performance Analysis Tool)

Table of Contents

1. perf 简介

perf 是 Linux 下的性能分析工具。

1.1. perf record

使用 perf record 可以采集性能数据,默认会在当前目录下生成名为 perf.data 的文件,如:

$ sudo perf record -p 25387 -F 300 --call-graph dwarf -- sleep 60

上面命令中, -p 用于指定进程 ID; -F 用于指定采集频率(如例子中是每秒 300 次); --call-graph 采用函数调用信息,可以设置为 fp (表示从 frame pointer 中得到函数调用信息,但如果程序编译时指定 --fomit-frame-pointer 则不会有这个信息),或者 dwarf (表示从 DWARF's CFI - Call Frame Information 中得到函数调用信息);最后的 sleep 60 表示采用 60 秒时间。

1.2. perf report

使用 perf report 可以读取 perf.data 文件(由一步 perf record 产生),显示性能报告。 perf report 执行后显示的是一个交互式的界面,如:

Samples: 279  of event 'cpu-clock', Event count (approx.): 561368088
  Children      Self  Command          Shared Object       Symbol
+   26.52%     0.00%  chronicle-weak-  perf-25387.map      [.] 0x00007f2844082de
+   26.52%     2.15%  chronicle-weak-  libjvm.so           [.] JVM_MonitorWait
+   24.01%     0.00%  VM Periodic Tas  libc-2.27.so        [.] __clone
+   24.01%     0.00%  VM Periodic Tas  libpthread-2.27.so  [.] start_thread
+   24.01%     0.00%  VM Periodic Tas  libjvm.so           [.] thread_native_ent
+   24.01%     0.00%  VM Periodic Tas  libjvm.so           [.] WatcherThread::ru
+   22.22%     1.08%  chronicle-weak-  libjvm.so           [.] ObjectSynchronize
+   21.86%     0.36%  VM Periodic Tas  libjvm.so           [.] WatcherThread::sl
+   20.79%     2.87%  chronicle-weak-  libjvm.so           [.] ObjectMonitor::wa
+   20.43%     1.08%  VM Periodic Tas  libjvm.so           [.] Monitor::wait
+   19.35%     0.72%  VM Periodic Tas  libjvm.so           [.] Monitor::IWait
+   17.92%     0.00%  G1 Young RemSet  libc-2.27.so        [.] __clone
+   17.92%     0.00%  G1 Young RemSet  libpthread-2.27.so  [.] start_thread

在这个交互式的界面中,可以用上下键头移动到你感兴趣的那行,再回车就会展开更详细的信息,如:

Samples: 279  of event 'cpu-clock', Event count (approx.): 561368088
  Children      Self  Command          Shared Object       Symbol              ◆
+   26.52%     0.00%  chronicle-weak-  perf-25387.map      [.] 0x00007f2844082d▒
+   26.52%     2.15%  chronicle-weak-  libjvm.so           [.] JVM_MonitorWait ▒
-   24.01%     0.00%  VM Periodic Tas  libc-2.27.so        [.] __clone         ▒
     __clone                                                                   ▒
     start_thread                                                              ▒
     thread_native_entry                                                       ▒
   - WatcherThread::run                                                        ▒
      + 21.86% WatcherThread::sleep                                            ▒
      + 2.15% PeriodicTask::real_time_tick                                     ▒
+   24.01%     0.00%  VM Periodic Tas  libpthread-2.27.so  [.] start_thread    ▒
+   24.01%     0.00%  VM Periodic Tas  libjvm.so           [.] thread_native_en▒
+   24.01%     0.00%  VM Periodic Tas  libjvm.so           [.] WatcherThread::r▒
+   22.22%     1.08%  chronicle-weak-  libjvm.so           [.] ObjectSynchroniz▒
+   21.86%     0.36%  VM Periodic Tas  libjvm.so           [.] WatcherThread::s▒
+   20.79%     2.87%  chronicle-weak-  libjvm.so           [.] ObjectMonitor::w▒

启动 perf report 时可以指定 --sort (-s) 为 pid, comm, dso, symbol, parent, cpu, socket, srcline, weight, local_weight, cgroup_id,以对结果进行排序。如指定 -s dso 就是按动态库排序:

$ perf report -s dso
Samples: 279  of event 'cpu-clock', Event count (approx.): 561368088
  Children      Self  Shared Object
+   78.49%    44.80%  libjvm.so
+   60.57%    14.34%  libpthread-2.27.so
+   45.52%     2.15%  libc-2.27.so
+   43.37%    11.47%  perf-25387.map
+   22.22%    22.22%  [kernel.kallsyms]
+    7.53%     2.87%  [vdso]
+    2.15%     2.15%  ld-2.27.so
+    1.79%     0.00%  libjava.so
+    1.08%     0.00%  libnio.so
......

指定 -s symbol 就是按 symbol 进行排序:

$ perf report -s symbol
Samples: 279  of event 'cpu-clock', Event count (approx.): 561368088
  Children      Self  Symbol
+   42.65%     0.00%  [.] __clone
+   42.65%     0.00%  [.] start_thread
+   42.65%     0.00%  [.] thread_native_entry
+   33.33%     4.30%  [.] os::PlatformEvent::park
+   26.52%     0.00%  [.] 0x00007f2844082dea
+   26.52%     2.15%  [.] JVM_MonitorWait
+   24.01%     0.00%  [.] WatcherThread::run
+   23.66%     1.08%  [.] Monitor::wait
+   22.58%     1.08%  [.] Monitor::IWait
+   22.22%     1.08%  [.] ObjectSynchronizer::wait
+   22.22%     0.00%  [k] 0xffffffffa4800081
+   21.86%     0.36%  [.] WatcherThread::sleep
......

2. 更直观地查看报告(火焰图)

前面介绍过使用 perf report 可以查看报告,但它不是方便。这里介绍另外一种方法:火焰图,通过火焰图可以更方便地找出性能瓶颈。

由 perf.data 生成“火焰图”(Flame Graph)的步骤如下:

$ perf script >out.perf                        # 由 perf.data 生成 out.perf
$ stackcollapse-perf.pl out.perf >out.folded   # 由 out.perf 生成 out.folded
$ flamegraph.pl out.folded >example.svg        # 由 out.folded 生成 火焰图 example.svg

上面例子中 perf script 是 perf 的相关组件,而 stackcollapse-perf.pl 和 flamegraph.pl 可以从 https://github.com/brendangregg/FlameGraph 下载。

再用浏览器打开 example.svg 既可以查看火焰图了。图 1 (摘自:https://github.com/antirez/redis/issues/7071 )是火焰图的一个例子。

perf_flame_graph.png

Figure 1: 火焰图例子

火焰图的 y 轴表示调用栈,每一层都是一个函数。调用栈越深,火焰就越高,顶部就是正在执行的函数,下方都是它的父函数。
火焰图的 x 轴表示抽样数,如果一个函数在 x 轴占据的宽度越宽,就表示它被抽到的次数多,即执行的时间长。注意,x 轴不代表时间,而是所有的调用栈合并后,按字母顺序排列的。
颜色没有特殊含义,因为火焰图表示的是 CPU 的繁忙程度,所以一般选择暖色调。

火焰图就是看顶层的哪个函数占据的宽度最大。只要有“平顶”(plateaus),就表示该函数可能存在性能问题。

从图 1 中可以发现函数 listSearchKey 是一个性能瓶颈,因为它占据的宽度最大,存在“平顶”(这个火焰图是对 Redis 服务器采样得到的,确实在某种场景下 listSearchKey 是性能瓶颈,这个问题已经在 Redis 中修复了,可以参考图片的出处)。

参考:http://www.ruanyifeng.com/blog/2017/09/flame-graph.html

Author: cig01

Created: <2019-12-01 Sun>

Last updated: <2020-04-20 Mon>

Creator: Emacs 27.1 (Org mode 9.4)