LinuxPerf

Posted 2022-03-04 宣之于口

Perf

Perf是内置于Linux内核源码树中的性能剖析(profiling)工具，它基于事件采样原理，以性能事件为基础，支持针对处理器相关性能指标与操作系统相关性能指标的性能剖析，常用于性能瓶颈的查找与热点代码的定位.

一、术语

• 硬件性能事件(Hardware event): 由 PMU硬件产生的事件, 在特定的条件下探测性能事件是否发生以及发生的次数, 比如 cache 命中
• 软件性能事件(Software event): 内核产生的事件，分布在各个功能模块中，统计和操作系统相关性能事件. 比如进程切换，tick 数等
• tracepoint event: 内核中的静态 tracepoint 所触发的事件，这些 tracepoint 用来判断程序运行期间内核的行为细节，比如 SLAB 分配器的分配次数等

二、使用

1. 参数

-C # 指定统计的CPU核心编号，不指定时统计全部核心（等价于-a）
-e # 指定统计事件
-p # 只统计特定pid指定的进程中产生的事件
-t # 只统计特定tid指定的线程中产生的事件
-K # 隐藏内核中的函数符号
-U # 隐藏用户态的函数符号
-g # perf record工具专用的参数，记录函数的调用栈信息

2. 命令

a. perf list

列出支持的内置事件列表, 即查看当前软硬件环境、支持的性能事件

List of pre-defined events (to be used in -e):

  alignment-faults                                   [Software event]
  bpf-output                                         [Software event]
  context-switches OR cs                             [Software event]
  cpu-clock                                          [Software event]
  cpu-migrations OR migrations                       [Software event]
  dummy                                              [Software event]
  emulation-faults                                   [Software event]
  major-faults                                       [Software event]
  minor-faults                                       [Software event]
  page-faults OR faults                              [Software event]
  task-clock                                         [Software event]

  msr/tsc/                                           [Kernel PMU event]

  rNNN                                               [Raw hardware event descriptor]
  cpu/t1=v1[,t2=v2,t3 ...]/modifier                  [Raw hardware event descriptor]
   (see 'man perf-list' on how to encode it)

  mem:<addr>[/len][:access]                          [Hardware breakpoint]

b. perf stat

用于统计分析系统或者特定软件的整体执行情况

$ perf stat -d gzip file1

 Performance counter stats for 'gzip file1':

    3952.239208  task-clock (msec)     #   0.999 CPUs utilized
              6  context-switches      #   0.002 K/sec
              0  cpu-migrations        #   0.000 K/sec
            127  page-faults           #   0.032 K/sec
 14,863,135,172  cycles                #   3.761 GHz                   (62.35%)
 18,320,918,801  instructions          #   1.23  insn per cycle        (74.90%)
  3,876,390,410  branches              # 980.809 M/sec                 (74.90%)
    135,062,519  branch-misses         #   3.48% of all branches       (74.97%)
  3,725,936,639  L1-dcache-loads       # 942.741 M/sec                 (75.09%)
    657,864,906  L1-dcache-load-misses #  17.66% of all L1-dcache hits (75.16%)
     50,906,146  LLC-loads             #  12.880 M/sec                 (50.01%)
      1,411,636  LLC-load-misses       #   2.77% of all LL-cache hits  (49.87%)

c. perf top

实时显示系统/进程的性能统信息

可以用于观察系统和软件内性能开销最大的函数列表。通过观察不同事件的函数列表可以分析出不同函数的性能开销情况和特点，判断其优化方向。例如如果某个函数在perf top -e instructions中排名靠后，却在perf top -e cache-misses和perf top -e cycles中排名靠前，说明函数中存在大量cache-miss造成CPU资源占用较多，就可以考虑优化该函数中的内存访问次数和策略，来减少内存访问和cache-miss次数，从而降低CPU开销

d. perf record/report

perf record: 记录一段时间内系统/进程的性能事件

定时采样: 下面采集执行频率是 99Hz(每秒99次)，如果99次都返回同一个函数名，那就说明 CPU 这一秒钟都在执行同一个函数，可能存在性能问题, 生成 perf.data 文件

# 对CPU所有进程以99Hz（每秒CPU的样本数）采集, 获取所有CPU的堆栈30秒
perf record -F 99 -a -g -- sleep 60  
# 对进程ID为181的进程进行采集
perf record -F 99 -p 181 -g -- sleep 60 

使用perf record可以将时间段内的情况记录下来，进行整个时段的分析，或者复制到其他设备上做后续分析，这是其他命令不支持的。perf record还有一个特别的参数-g，可以支持记录函数的调用关系。使用这个参数，就不止能够看到性能开销高的函数列表，还能看到这些函数是如何被调用和使用的。在很多情况下，性能开销高的函数都是memcpy之类的系统基础函数，其本身是没有什么优化空间的，能够优化的是调用memcpy的方式和次数。通过perf record -g就能够分析出这些函数的调用关系，从而找到真正需要优化的代码位置

perf report: 取perf.data 文件，并显示分析数据

3. 示例

记录CPU堆栈：要查找CPU瓶颈，请定时记录堆栈：

# 系统范围
perf record -ag -F 97
# 特定进程
perf record -p 188 -g -F 97
# 特定 workload
perf record -g -F 97 -- ./myapp

三、观察Java进程的CPU使用情况

分析Java代码，为了帮助perf找出Java代码的函数名，可以使用perf-map-agent，它附加到Java进程并生成将动态生成的Java机器代码映射到类和方法名的映射文件。 perf-map-agent还可以通过一组方便的脚本（例如perf-java-record-stack和perf-java-report-stack）为您运行整个记录会话

1. 安装

首先需要安装perf-map-agent

git clone https://github.com/jvm-profiling-tools/perf-map-agent 
yum install cmake 
cmake . 
make

这里我遇到了一个问题: Centos 7, cmake 版本：2.8.12.2

CMake Error: The following variables are used in this project, but they are set to NOTFOUND.
Please set them or make sure they are set and tested correctly in the CMake files:
JAVA_INCLUDE_PATH (ADVANCED)
   used as include directory in directory /root/perf-map-agent
JAVA_INCLUDE_PATH2 (ADVANCED)
   used as include directory in directory /root/perf-map-agent

解决办法：安装开发环境yum install java-1.8.0-openjdk-devel.x86_64

2. 使用

在启动Java进程的时候添加-XX:+PreserveFramePointer参数

java -XX:+PreserveFramePointer <application name>

在perf-map-agent/bin目录下有很多脚本：

create-java-perf-map.sh  dtrace-java-record-stack  perf-java-record-stack
create-links-in          dtrace-perf-map.pl        perf-java-report-stack
dtrace-java-flames       perf-java-flames          perf-java-top

使用：

./perf-java-top <pid> <perf-top-options>
./perf-java-report-stack <pid> <perf-record-options>

四、实验

本实验参照该实验手册：linux-tracing-workshop

Task 1: Compile the Profiled Application

您将要分析的应用程序是一个非常简单的命令行工具，它可以计算给定范围内的质数，并使用OpenMP来并行化计算。 但是首先，让我们构建它并确保一切正常:

# 出现 ... only allowed in C99 mode, 故加上 -std=c99 参数 
gcc -g -fno-omit-frame-pointer -std=c99 -fopenmp primes.c -o primes

现在，通过运行以下命令，尝试使用不同数量的线程对该应用程序进行多次执行：

创建test.sh

for i in `seq 1 2 16`; do \\
  OMP_NUM_THREADS=$i bash -c 'time ./primes'; \\
done

创建足够多的线程以在整个运行过程中使所有core保持饱和时，经过的时间应保持稳定。由于线程之间的工作分配不是理想的，因此在N核系统上，您将需要N个以上的线程来使它们全部繁忙

$ sh test.sh
real	0m3.858s
user	0m7.436s
sys	0m0.006s
Primes found: 17984

real	0m3.863s
user	0m7.513s
sys	0m0.001s
Primes found: 17984

[...]

Task 2: Profile with perf

该任务旨在使用perf找出为什么花费很长时间计算素数

export OMP_NUM_THREADS=16
# -g 表示希望获取调用堆栈; -F 设置采样频率为997/s; 
perf record -g -F 997 -- ./primes

要找出瓶颈所在，请查看性能报告：似乎在is_divisible上花费了很多时间

$ perf report --stdio

# Children      Self  Command  Shared Object       Symbol
# ........  ........  .......  ..................  ...............................
#
    99.93%     0.01%  primes   primes              [.] main._omp_fn.0
            |
             --99.92%--main._omp_fn.0
                       |
                       |--99.20%--is_prime
                       |          |
                       |           --85.40%--is_divisible
                       |
                        --0.72%--is_divisible

    99.46%     0.00%  primes   [unknown]           [.] 0xec45c7d87d894828

如果想要知道确切的位置: perf annotate, 显示perf.data函数代码

Percent│            return n % d == 0;
       │      mov    -0x4(%rbp),%eax
  4.95 │      cltd
  0.06 │      idivl  -0x8(%rbp)
 75.45 │      mov    %edx,%eax
  3.57 │      test   %eax,%eax
  2.23 │      sete   %al
  2.78 │      movzbl %al,%eax
       │    
  5.37 │      pop    %rbp
  0.84 │    ← retq

Task 3: Extract a Flame Graph

在实际项目中，性能报告文件会非常大：

$ perf report --stdio | wc -l
1234

这时可以借助火焰图帮忙分析， 参考火焰图章节

$ perf script > primes.stacks
$ FlameGraph/stackcollapse-perf.pl primes.stacks > primes.collapsed
$ FlameGraph/flamegraph.pl primes.collapsed > primes.svg

Task 4: Profiling Java Code

首先，运行我们将要分析的Java应用程序。 它是同一主要计数应用程序的Java版本：

$ java -XX:+PreserveFramePointer slowy/App
Press ENTER to start.

暂时不要按ENTER, 在另一个shell中运行jps找到Slowy应用程序的进程ID

$ jps
30967 App
31018 Jps

然后运行收集工具，运行perf-java-report-stack之后，

在Java应用程序的控制台中按ENTER，以便收集工具记录一些有意义的工作

# 进入perf-map-agent/bin目录
$ ./perf-java-report-stack 30967
Recording events for 15 seconds (adapt by setting PERF_RECORD_SECONDS)

  Children      Self  Command  Shared Object       Symbol
+  100.00%     0.00%  java     libpthread-2.17.so  [.] start_thread
+  100.00%     0.00%  java     libjli.so           [.] JavaMain
+  100.00%     0.00%  java     libjvm.so           [.] jni_CallStaticVoidMethod
+  100.00%     0.00%  java     libjvm.so           [.] jni_invoke_static
+  100.00%     0.00%  java     libjvm.so           [.] JavaCalls::call_helper
+  100.00%     0.00%  java     perf-30967.map      [.] call_stub
+   67.12%    67.12%  java     perf-30967.map      [.] Lslowy/App;::main
+   32.60%    32.60%  java     perf-30967.map      [.] Lslowy/App;::isPrime
+   21.37%     0.00%  java     perf-30967.map      [.] Lslowy/App;::main
+   11.51%     0.27%  java     perf-30967.map      [.] Interpreter

可以看出性能报告，显示Java程序中的瓶颈：App;::main 和 App;::isPrime。因为较小的方法已被优化（内联）。

重复实验, 设置 -XX:-Inline防止此优化并获得更准确的结果

[...]
  Children      Self  Command  Shared Object       Symbol
+   93.28%    22.09%  java     perf-31821.map      [.] Lslowy/App;::isPrime
+   77.91%    77.76%  java     perf-31821.map      [.] Lslowy/App;::isDivisible
+   67.76%     0.00%  java     perf-31821.map      [.] Lslowy/App;::main
+   21.19%     0.00%  java     perf-31821.map      [.] Lslowy/App;::main
+   11.04%     0.00%  java     perf-31821.map      [.] Interpreter
     0.15%     0.15%  java     [kernel.kallsyms]   [k] nf_iterate
     0.15%     0.00%  java     [unknown]           [.] 0xffffffffbb18436a
[...]

上述会生成/tmp/perf-PID.data，可以生成相应的火焰图

# 请注意--colors = java参数，该参数指示flamegraph.pl脚本根据函数的类型对函数进行着色：Java方法，本机方法和内核方法都将具有自己独特的调色板。
$ perf script -i /tmp/perf-PID.data | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl --colors=java > java.svg

参考文献

Perf分析CPU性能问题笔记

cmake error(cmake version is 2.8.12.2)

Git:perf-map-agent