Perf与火焰图

1 安装 perf

perf 命令（performance 的缩写）是 Linux 系统原生提供的性能分析工具，会返回 CPU 正在执行的函数名以及调用栈（stack）。通常，它的执行频率是 99Hz（每秒 99 次），如果 99 次都返回同一个函数名，那就说明 CPU 这一秒钟都在执行同一个函数，可能存在性能问题。

1.1 使用 apt 安装

1
2
3
4
sudo apt install linux-tools-common
sudo apt install linux-tools-`uname -r`
# 通过以下命令验证安装是否成功
perf --version

1.2 使用源码编译安装

1
2
3
4
5
6
7
8
9
10
11
12
13
# 检查内核版本
uname -r
# 下载内核源码
wget http://ftp.sjtu.edu.cn/sites/ftp.kernel.org/pub/linux/kernel/v4.x/linux-4.19.tar.gz
# 安装依赖并解压
sudo apt install -y build-essential bison flex libssl-dev libelf-dev libcap-dev libattr1-dev libncurses-dev
tar -zxvf linux-4.19.tar.gz
cd linux-4.19/tools/perf/
# 编译安装
make perf -j8 V=1
make perf install DESTDIR=/usr/local V=1
# 通过以下命令验证安装是否成功
perf --version

2 使用 perf

2.1 perf record

perf record 记录单个函数级别的统计信息。

1
sudo perf record -F 99 -p 13204 -g -- sleep 30

上面的代码中，perf record表示记录，-F 99表示每秒 99 次，-p 13204是进程号，即对哪个进程进行分析，-g表示记录调用栈，sleep 30则是持续 30 秒。

运行后会产生一个庞大的文本文件。如果一台服务器有 16 个 CPU，每秒抽样 99 次，持续 30 秒，就得到 47,520 个调用栈，长达几十万甚至上百万行。

2.2 perf report

perf report命令可以统计每个调用栈出现的百分比，然后从高到低排列。

1
sudo perf report -a --stdio

2.3 perf list

列出所有能够触发 perf 采样点的事件,主要区分为如下三类事件：

  • Hardware Event 是由 PMU 硬件产生的事件，比如 cache 命中
  • Software Event 是内核软件产生的事件，比如进程切换，tick 数等
  • Tracepoint event 是内核中的静态 tracepoint 所触发的事件
1
sudo perf list

2.4 perf top

用于实时显示当前系统的性能统计信息。该命令主要用来观察整个系统当前的状态，比如可以通过查看该命令的输出来查看当前系统最耗时的内核函数或某个用户进程。

1
sudo perf top

2.5 perf script

Tom Zanussi 将 perl 和 python 解析器嵌入到 perf 程序中，从而使得 perf 能够自动执行 perl 或者 python 脚本进一步进行处理，从而为 perf 提供了强大的扩展能力。因为任何人都可以编写新的脚本，对 perf 的原始输出数据进行所需要的进一步处理。

1
sudo perf script > out.perf

3 火焰图

3.1 简介

火焰图是基于 perf 结果产生的 SVG 图片，用来展示 CPU 的调用栈。

y 轴表示调用栈，每一层都是一个函数。调用栈越深，火焰就越高，顶部就是正在执行的函数，下方都是它的父函数。

x 轴表示抽样数，如果一个函数在 x 轴占据的宽度越宽，就表示它被抽到的次数多，即执行的时间长。注意，x 轴不代表时间，而是所有的调用栈合并后，按字母顺序排列的。

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

可通过 GITHUB 直接下载：

1
git clone https://github.com/brendangregg/FlameGraph.git

3.2 使用方式

1
2
3
4
5
6
cd /path/to/FlameGraph

perf record -F 99 -a -g -- sleep 60
perf script > out.perf
./stackcollapse-perf.pl out.perf > out.folded
./flamegraph.pl out.kern_folded > kernel.svg

火焰图是 SVG 图片，可以与用户互动。

  • 鼠标悬浮。火焰的每一层都会标注函数名，鼠标悬浮时会显示完整的函数名、抽样抽中的次数、占据总抽样次数的百分比。

  • 点击放大。在某一层点击，火焰图会水平放大，该层会占据所有宽度，显示详细信息。左上角会同时显示”Reset Zoom”，点击该链接，图片就会恢复原样。

  • 搜索。按下 Ctrl + F 会显示一个搜索框，用户可以输入关键词或正则表达式，所有符合条件的函数名会高亮显示。

4 范例

例 1

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
perf top -e cycles:k #显示内核和模块中，消耗最多 CPU 周期的函数

perf top -e kmem:kmem_cache_alloc #显示分配高速缓存最多的函数

perf top

Samples: 1M of event 'cycles', Event count (approx.): 73891391490
 5.44% perf [.] 0x0000000000023256
 4.86% [kernel] [k] \_spin_lock
 2.43% [kernel] [k] \_spin_lock_bh
 2.29% [kernel] [k] \_spin_lock_irqsave
 1.77% [kernel] [k] **d_lookup
 1.55% libc-2.12.so [.] **strcmp_sse42
 1.43% nginx [.] ngx_vslprintf
 1.37% [kernel] [k] tcp_poll

第一列：符号引发的性能事件的比例，默认指占用的 cpu 周期比例。
第二列：符号所在的 DSO(Dynamic Shared Object)，可以是应用程序、内核、动态链接库、模块。
第三列：DSO 的类型。[.]表示此符号属于用户态的 ELF 文件，包括可执行文件与动态链接库)。[k]表述此符号属于内核或模块。
第四列：符号名。有些符号不能解析为函数名，只能用地址表示。

例 2

1
2
3
4
5
6
7
8
9
10
11
perf top -g #得到调用关系图

perf top -e cycles #指定性能事件

perf top -p 23015,32476 #查看这两个进程的 cpu cycles 使用情况

perf top -s comm,pid,symbol #显示调用 symbol 的进程名和进程号

perf top --comms nginx,top #仅显示属于指定进程的符号

perf top --symbols kfree #仅显示指定的符号

例 3

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
perf stat ls

Performance counter stats for 'ls':

          0.653782 task-clock                #    0.691 CPUs utilized
                 0 context-switches          #    0.000 K/sec
                 0 CPU-migrations            #    0.000 K/sec
               247 page-faults               #    0.378 M/sec
         1,625,426 cycles                    #    2.486 GHz
         1,050,293 stalled-cycles-frontend   #   64.62% frontend cycles idle
           838,781 stalled-cycles-backend    #   51.60% backend  cycles idle
         1,055,735 instructions              #    0.65  insns per cycle
                                             #    0.99  stalled cycles per insn
           210,587 branches                  #  322.106 M/sec
            10,809 branch-misses             #    5.13% of all branches

       0.000945883 seconds time elapsed

    输出包括ls的执行时间，以及10个性能事件的统计。

    task-clock：任务真正占用的处理器时间，单位为ms。CPUs utilized = task-clock / time elapsed，CPU的占用率。

    context-switches：上下文的切换次数。

    CPU-migrations：处理器迁移次数。Linux为了维持多个处理器的负载均衡，在特定条件下会将某个任务从一个CPU

    迁移到另一个CPU。

    page-faults：缺页异常的次数。当应用程序请求的页面尚未建立、请求的页面不在内存中，或者请求的页面虽然在内

    存中，但物理地址和虚拟地址的映射关系尚未建立时，都会触发一次缺页异常。另外TLB不命中，页面访问权限不匹配

    等情况也会触发缺页异常。

    cycles：消耗的处理器周期数。如果把被ls使用的cpu cycles看成是一个处理器的，那么它的主频为2.486GHz。

    可以用cycles / task-clock算出。

    stalled-cycles-frontend：略过。

    stalled-cycles-backend：略过。

    instructions：执行了多少条指令。IPC为平均每个cpu cycle执行了多少条指令。

    branches：遇到的分支指令数。branch-misses是预测错误的分支指令数。

perf stat -r 10 ls > /dev/null #执行 10 次程序，给出标准偏差与期望的比值

perf stat -v ls > /dev/null #显示更详细的信息

perf stat -n ls > /dev/null #只显示任务执行时间，不显示性能计数器

perf stat -a -A ls > /dev/null #单独给出每个 CPU 上的信息

perf stat -e syscalls:sys_enter ls #ls 命令执行了多少次系统调用

例 4

1
2
3
4
5
perf record -p `pgrep -d ',' nginx` #记录 nginx 进程的性能数据

perf record ls -g #记录执行 ls 时的性能数据

perf record -e syscalls:sys_enter ls #记录执行 ls 时的系统调用，可以知道哪些系统调用最频繁

例 5

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
perf lock record ls #记录

perf lock report #报告

                Name   acquired  contended total wait (ns)   max wait (ns)   min wait (ns)

&mm->page*table*... 382 0 0 0 0
&mm->page*table*... 72 0 0 0 0
&fs->lock 64 0 0 0 0
dcache_lock 62 0 0 0 0
vfsmount_lock 43 0 0 0 0
&newf->file_lock... 41 0 0 0 0

Name：内核锁的名字。
aquired：该锁被直接获得的次数，因为没有其它内核路径占用该锁，此时不用等待。
contended：该锁等待后获得的次数，此时被其它内核路径占用，需要等待。
total wait：为了获得该锁，总共的等待时间。
max wait：为了获得该锁，最大的等待时间。
min wait：为了获得该锁，最小的等待时间。

例 6

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
perf kmem record ls #记录

perf kmem stat --caller --alloc -l 20 #报告

---

Callsite | Total_alloc/Per | Total_req/Per | Hit | Ping-pong | Frag

perf_event_mmap+ec | 311296/8192 | 155952/4104 | 38 | 0 | 49.902%
proc_reg_open+41 | 64/64 | 40/40 | 1 | 0 | 37.500%
\_\_kmalloc_node+4d | 1024/1024 | 664/664 | 1 | 0 | 35.156%
ext3_readdir+5bd | 64/64 | 48/48 | 1 | 0 | 25.000%
load_elf_binary+8ec | 512/512 | 392/392 | 1 | 0 | 23.438%

Callsite：内核代码中调用 kmalloc 和 kfree 的地方。
Total_alloc/Per：总共分配的内存大小，平均每次分配的内存大小。
Total_req/Per：总共请求的内存大小，平均每次请求的内存大小。
Hit：调用的次数。
Ping-pong：kmalloc 和 kfree 不被同一个 CPU 执行时的次数，这会导致 cache 效率降低。
Frag：碎片所占的百分比，碎片 = 分配的内存 - 请求的内存，这部分是浪费的。
有使用--alloc 选项，还会看到 Alloc Ptr，即所分配内存的地址。

例 7

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
perf sched record sleep 10

perf report latency --sort max

---

Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |

---

events/10:61 | 0.655 ms | 10 | avg: 0.045 ms | max: 0.161 ms | max at: 9804.958730 s
sleep:11156 | 2.263 ms | 4 | avg: 0.052 ms | max: 0.118 ms | max at: 9804.865552 s
edac-poller:1125 | 0.598 ms | 10 | avg: 0.042 ms | max: 0.113 ms | max at: 9804.958698 s
events/2:53 | 0.676 ms | 10 | avg: 0.037 ms | max: 0.102 ms | max at: 9814.751605 s
perf:11155 | 2.109 ms | 1 | avg: 0.068 ms | max: 0.068 ms | max at: 9814.867918 s

TASK：进程名和 pid。
Runtime：实际的运行时间。
Switches：进程切换的次数。
Average delay：平均的调度延迟。
Maximum delay：最大的调度延迟。
Maximum delay at：最大调度延迟发生的时刻。

例 8

1
2
3
perf probe --line schedule #前面有行号的可以探测，没有行号的就不行了

perf report latency --sort max #在 schedule 函数的 12 处增加一个探测点
环境搭建
#Linux #kernel #perf #flamegraph
Perf与火焰图
https://zdawng.github.io/posts/6121d6c0/
作者
ZDawnG
发布于
2023年9月9日
许可协议