CPU Profiling 经验之谈

记录了自己在执行 CPU Profiling 的时候遇到的一些经验。

相关文章：

1. heap profiling

Profiling 基础

首先，Performance analysis and tuning on modern CPUs 这本书是值得阅读的基础。但是里面讲述的很多内容，目前还没有机会完全实践。

CPU 常见问题分类

retiring 和 IPC：

• CPU 的有效指令的比例可以看 retiring 这个指标。如果很多周期在 pipeline stall 或者预测失败，那么 retiring 就会很低。
• IPC 是平均每个时钟周期执行了多少条指令。

两者的关系可以看成 IPC = 理论最大 IPC × Retiring 比例

• front end 问题
  主要是取指和译码阶段效率问题。perf stat 显示 stalled-cycles-frontend 比例高，IPC 低。
  • Icache miss 指令缓存未命中
    程序太大 / 跳转太多
  • ITLB miss 指令 TLB 未命中
    大代码页切换频繁
  • Branch misprediction 分支预测失败
  • Decode bandwidth 译码吞吐不足
    x86 CISC 指令复杂
  • Uop cache miss 微指令缓存未命中，需重新译码
• back end 问题
  主要是执行或访存阶段受阻。
  • Execution Bound
    一般体现为 CPU 满、IPC 高、火焰图能看到明显热点。
  • Memory Bound
    主要是访存相关问题。一般体现为 CPU 利用率低，IPC 低，cache miss rate 高，火焰图没有明显热点。

On CPU 和 Off CPU time

我们常常要回答问题，为什么 CPU 没有被用满，但是某个函数依然比较慢。此时需要考虑：

• Off-CPU 时间
  例如在等待阻塞 IO、锁、page swap 等的时间。这些时间不会通过 On CPU 火焰图被反映出来，但却是影响读取性能的一个因素。
• 访存问题
  如果 CPU 在等待数据（load miss -> L3 miss -> DRAM），流水线会停住，没有指令被 retire，于是 CPU 的利用率就会变低。但此时，CPU 实际上是在等内存。在后面的“CPU Utilization(%CPU) 的理解”章节中，会讨论到这个问题。此类问题非常常见，伪共享就是一个例子。

锁和等待相关的 On CPU 时间

在火焰图中，也能看到一些和 mutex 或者 futex 有关的 CPU 开销。这是因为：

• spinlock 可能存在忙等
• 高竞争下 futex 会反复执行内核代码

设计上的 pitfall

• 循环中的虚函数调用
• memcpy

CPU Utilization(%CPU) 的理解

在 Brendan Gregg 的博客中纠正了一个概念，理解 CPU 的利用率，应该注意到除了 Busy 和 Idle 之外，它还有一个 Stall 态。在 Stall 态中，CPU 主要在等待内存。Brendan Gregg 用了下面这张图来说明 Stall 的占比还是挺大的。

问题是，但是 CPU Utilization(%CPU) 无法区分 Busy 和 Stall。这里面的通用做法是在 context switch 的时候，记录 idle time 等。但是，因为现如今 CPU 比内存越来越快，所以如果通过 top 命令能看到 CPU 很高，但其实问题根因越来越有可能是拉胯的是访存速度。

作者给出了方案是利用 Performance Monitoring Counters (PMCs)

perf stat -a -- sleep 10

主要要关注 instructions per cycle (insns per cycle: IPC)。它表示了 CPU 的每个 clock cycle 中多少个指令被执行了。CPU 有一个参数表示它一个 cycle 可以 retire 多少个指令（是指的 superscalar 么？）。例如在知道下面 CPU 的 issue width 是 4-wide 之后，下面的 0.78 的 IPC 就显得比较低了。

# perf stat -a -- sleep 10

 Performance counter stats for 'system wide':

     641398.723351      task-clock (msec)         #   64.116 CPUs utilized            (100.00%)
           379,651      context-switches          #    0.592 K/sec                    (100.00%)
            51,546      cpu-migrations            #    0.080 K/sec                    (100.00%)
        13,423,039      page-faults               #    0.021 M/sec                  
 1,433,972,173,374      cycles                    #    2.236 GHz                      (75.02%)
   <not supported>      stalled-cycles-frontend  
   <not supported>      stalled-cycles-backend   
 1,118,336,816,068      instructions              #    0.78  insns per cycle          (75.01%)
   249,644,142,804      branches                  #  389.218 M/sec                    (75.01%)
     7,791,449,769      branch-misses             #    3.12% of all branches          (75.01%)

      10.003794539 seconds time elapsed

使用 perf probe 记录函数调用耗时

该方案整理自某同事的 idea。

考虑下面的场景，需要查看某动态链接库 /path/to/libtiflash_proxy.so 中 handle_pending_applies 函数每次调用的耗时。此时，可以借助 perf probe 去打点 $tok 和 $tok%return，它们分别对应函数入口和函数出口。这里需要借助于一个 while 循环是因为函数可能有多个重载。

perf probe --del 'probe_libtiflash_proxy:*'
BIN=/path/to/libtiflash_proxy.so
TOKEN=handle_pending_applies
ITER=0
objdump $BIN --syms | grep $TOKEN | awk '{print $6}' | while read -r tok ; do
    ITER=$(expr $ITER + 1)
    NAME=$TOKEN\_$ITER
    echo $NAME, $TOKEN, $ITER, $TOKEN\_$ITER
    perf probe -x $BIN --no-demangle $NAME=$tok
    perf probe -x $BIN --no-demangle $NAME=$tok%return
done
perf record -e probe_libtiflash_proxy:\* -aR sleep 10
perf script -s perf-script.py

附上 perf-script.py

关于线程池

记录线程名

有一些方法设置线程名，包括：

1. pthread_setname_np
2. prctl

出于下列原因，建议线程名具有唯一性：

1. 诸如一些线程池的实际工作内容不一样，最好以数字区分。
2. 有一些库会扩展 std::mutex，记录上锁的线程名，用来避免重复加锁。当然这个并不好，最好用线程 id。

在一些很老的 C 库中，没有提供 pthread_setname_np 函数。CK 会写一个 dummy 的函数来替换，这可能导致一些情况下不能设置成功线程名。

线程名的切换问题

一些程序会同时记录所有线程的 CPU 用量，以及当前进程的 CPU 总用量。这两个是一致的么？至少在一个使用线程池的程序中，未必一致。

这里的原因是线程池中往往会将线程按照 ${task_name}_${task_id} 这样重新命名，从而区分用途。而处于避免线程启动和销毁的开销，又倾向于维护一个全局常驻线程池，新开辟的线程池会先尝试从这个全局线程池中取，然后用完之后再归还。这就导致如果在这个过程中线程名字发生了从 A 到 B 的变换，则可能会看到 B 对应的指标有一个很高的 delta（比如在 grafana 中能看到一个尖峰）。原因是 /proc/$pid/stat 或者 /proc/tasks/$tid/stat 里面的信息都是从启动开始经历的时钟周期，无论是 stime 还是 utime。所以，如果一开始线程名是 A，后来被某个线程池借走了，名字变成 B，但此时 A 的数据还在。如果此时，线程被归还了，名字改为 A，那么 A 的变化率就是这段时间的 jiffies 增量除以这段时间的长度。

常见 profiling 工具和实现原理

名称	主要作用	所在位置
CPU PMU（性能监控单元）	对周期、完成的指令、缓存未命中等硬件事件计数	CPU 硬件
perf_events	Linux 的性能观测子系统，管理事件、计数、采样及数据接口	内核态
perf 命令	配置采集、读取结果、保存数据和生成报告	用户态
用于性能采集的 eBPF 程序	在事件触发时执行自定义采集、过滤和统计逻辑	内核态
eBPF agent / 加载器	加载 BPF 程序、读取结果、解析和导出数据	用户态
pprof 命令	读取 profile，生成热点排行、调用图、火焰图等	用户态
Go runtime/pprof	在 Go 应用内部提供 CPU、堆、阻塞等 profiling 功能	用户态进程内部
nsys	NVIDIA Nsight Systems 的命令行工具

Linux 内核

kprobe / uprobe 在 Linux kernel 中，负责在内核态或者用户态动态插桩，真正 hook 某条指令。

gprof(GNU Profiler)

采用函数级别插桩(instrumentation)+ 周期性的 PC sampling 的方式。基础功能如看调用耗时和调用关系是没问题的。但是涉及如下的就比较捉襟见肘：

• CPU hardware counters
• Kernel profiling
• 多线程
• 动态 prob

perf

由 perf record 和 perf script 组成：

• perf record
  负责采集
  输出：perf.data
• perf script
  负责解析已有数据
  输入：perf.data
  输出：文本形式的 sample

特点：

• 使用 Linux 内核的 perf_event 接口，这个接口在后面专门介绍
• 支持 sample-based 和事件统计 event-based
• 基于硬件性能计数器如 CPU cycles, cache misses

其实现原理大概是由 CPU PMU / timer / software event 驱动的。

perf
 │
 │ perf_event_open()
 ↓
Linux perf_event subsystem
 │
 ↓
CPU PMU / timer / software event
 │
 ├── interrupt
 ├── sample PC
 └── sample call stack

另一个特点是：

• gprof 是 instrumentation，对于高频调用的函数，每次调用都会执行 mcount()，从而产生很大的 overhead。
• perf 是 sampling，开销主要随采样频率、调用栈深度和采集内容变化，得到的是统计意义上的 CPU 时间分布。

Intel VTune Profiler

Google CPU Profiler(pprof + gperftools)

Linux prof_events

perf_events 的核心位于内核，但它可以观测用户态程序。一个事件由内核报告，并不意味着它只对应内核态执行。

                   user space

              ┌──────────────┐
              │     perf     │
              └──────┬───────┘
                     │
                     │ perf_event_open()
                     ↓

                   kernel

           ┌─────────────────────┐
           │     perf_event      │
           │      framework      │
           └─────────┬───────────┘
                     │
      ┌──────────────┼──────────────┐
      ↓              ↓              ↓

    PMU          tracepoint       kprobe
cycles             sched          uprobe
cache miss
branch miss

调用栈回溯与 profiling 开销

这里比较 pprof-rs 和 perf 对 Linux 用户栈的采集，以 x86-64 为例。pprof-rs 的 FP 指 frame-pointer feature，DWARF 指默认的 backtrace-rs → _Unwind_Backtrace 路径，其他 unwinder 需要另看。下面是按所链接源码做的机制分析，没有跑 benchmark，具体实现还要看版本。

FP 和 DWARF

1. unwind：从当前执行位置逐层找调用者，得到一串代码地址，也就是调用栈回溯。
2. 聚合：把相同的调用栈合并计数，例如某条栈被采到 80 次，就记为 80。
3. 符号化：把地址转换成函数名、文件和行号，addr2line 还可以解析 inline 调用链。

FP(Frame Pointer) 的方法比较直接。以常规 x86-64 帧布局为例，RSP 是栈指针(SP)，RBP 用作帧指针。函数通过 push rbp; mov rbp, rsp 建好帧之后，[RBP] 保存上一帧的 RBP，[RBP + 8] 保存返回地址。这样沿着 RBP 链往上走，就能得到调用栈，前提是相关代码保留了可用的 FP。

编译器可以省略 FP，少做保存、建立和恢复帧指针的操作，并把 RBP 用于其他计算。但这不代表没有栈了，RSP 仍然在，局部变量也可以相对 RSP 寻址。问题是各个函数分配的栈空间不同，仅凭 RSP，无法按统一的固定偏移找到返回地址。

DWARF 的办法是由编译器生成 CFI(Call Frame Information)，描述在某个指令位置如何恢复调用者状态。CFA(Canonical Frame Address) 是按规则算出的基准地址，在这个例子里就是调用该函数之前的栈指针；memory64 表示读取 8 字节。恢复出调用者的 PC 和 RSP 后，就可以继续找上一层的 CFI。

例如，假设某函数分配了 24 字节局部空间，加上 call 压入的 8 字节返回地址，函数主体处的规则可以写成：

CFA = RSP + 32
调用者 PC = memory64[CFA - 8]
调用者 RSP = CFA

考虑 main → A → f 和 main → B → f，两次都采在 f 的同一条指令。此时 PC 选出的规则相同，但栈里保存的返回地址不同，因此能够区分 A 和 B。CFI 给出规则，寄存器和栈内存给出这一次调用的实际状态。 unwind 只是读取这些信息，不会真的让函数返回。

容易混淆的地方：

• CFI 可以放在 .eh_frame 中，保留可用的回溯信息就可能恢复地址调用链，不要求同时带上完整的 -g 调试信息。文件、行号等信息则需要另看。
• 使用 FP 回溯后，仍然可以用 DWARF 调试信息做符号化，包括解析 inline。选择 FP，并不等于省掉 addr2line。
• DWARF 是描述调试信息和栈展开规则的一套格式，.eh_frame 则是 Linux 可执行文件和动态库中存放栈展开规则的一个数据区。名字里的 eh 是 Exception Handling，也就是异常处理，因为抛出异常时也需要沿调用栈找到上层函数。编译器会把“执行到这里时，返回地址存在哪里、如何恢复调用者的寄存器”等规则写进去，采样器再结合当时的寄存器和栈内存，一层层找回调用者。pprof-rs 默认的 Linux 回溯路径通常就依赖这些规则。因此，没有开启 -g 生成完整调试信息，程序也可能保留 .eh_frame，照样能回溯出一串调用地址。至于这些地址对应哪个源码文件、哪一行，则需要 addr2line 等符号化工具读取另外的调试信息来解析。
• debug = 1 提供的调试信息，和回溯调用栈需要的规则，回答的是不同的问题。只有 debug = 1、缺少可用的展开信息，并不是 DWARF 展栈成功的原因。当然，常见 Linux Rust 构建通常本来就会生成 .eh_frame，所以只加 debug = 1，实际往往也能正常回溯。 只是展开表并不是 debug = 1 保证提供的。

CFI 的规则和输出位置可以参考 GNU as 文档。

pprof-rs 和 perf 的区别

两者都支持 FP 和 DWARF，需要分别比较。按 perf 的 record → report/script 流程看：

方案	采样时做什么	后续分析做什么
pprof-rs FP	在业务线程的 SIGPROF handler 中沿 FP 链回溯、检查地址并聚合	业务进程内符号化、生成报告
pprof-rs DWARF	在业务线程的 SIGPROF handler 中按 CFI 回溯并聚合	业务进程内符号化、生成报告
perf FP（常规模式）	在内核采样上下文沿用户 FP 链回溯，记录地址链	分析进程内符号化
perf DWARF	保存寄存器和用户栈快照	分析进程内按 CFI 回溯，再符号化

具体可以对照 pprof-rs 采样实现和 perf 的 post-unwinding 配置。

对于 FP，两者都是沿链找返回地址，但 pprof-rs 还有额外工作。当前的实现每帧会调用 validate()，其地址检查在稳定成功路径上通常包含一次 pipe read 和 write。Linux 下还会通过 _Unwind_FindEnclosingFunction 查函数起始地址，用于聚合。这个查找也需要开销，不过和解析文件、行号的完整 addr2line 需要分开看。因此，不能把 perf FP 的开销直接套到 pprof-rs FP 上。

对于 DWARF，主要区别是 CFI unwind 在什么时候做。pprof-rs 在信号处理时做，会占用收到信号的业务线程；perf 把它放到后续分析阶段，但现场需要拷贝栈、写出数据。perf 的默认栈 dump 大小是 8 KiB，假设每秒 1,000 个样本、每次拷贝满，仅栈数据就约 7.8 MiB/s。减小快照又可能截断调用栈，所以也不是越小越好。

addr2line 和报告生成

pprof-rs 的 FP 和默认 backtrace 路径都会通过 backtrace-rs 做符号化，通常在 report().build() 中逐帧解析已聚合的栈。因此，改成 FP 主要改变采样时的回溯方式，报告生成仍然会消耗业务进程的 CPU 和内存。

在内存监控那篇文章里记录过，预期 10s 的 profile，实际花了一分钟左右，其中约 40s 花在生成火焰图上，涉及 debug section 解压缩和 addr2line。这类问题就需要把采样和报告生成拆开看。

perf 的符号化由 report/script 分析进程承担，也方便放到其他机器执行。当然，这不代表总耗时一定更少，只是这部分资源消耗可以移出业务进程。

比较时至少要分别记录：

• 采样期间的额外 CPU、业务吞吐和延迟。
• 报告生成的 CPU 时间、耗时和峰值 RSS，以及 perf 的记录数据量。

此外还要对齐实际样本数、有效栈深、编译选项，以及是否解析行号和 inline。单看 unwind，可以用“每秒实际样本数 × 单次 unwind 耗时”估算 CPU 消耗。例如假设每次 10 μs、每秒 1,000 次，就是一个 CPU 核的 1%；这只是计算例子，也不等于吞吐下降 1%。

关于 benchmark

pitfall

• 需要多次运行
• 需要预热，加载缓存
  通常可以使用启发式的方法，等待性能收敛。
• 使用高精度时钟
• 监控系统负载
• 避免编译器优化
• 缓存影响
• 关注压测程序本身的资源开销，如 CPU 等

考虑点：

• 如何按照进度较高的 QPS 进行压测
• 考虑动态内存分配如 new 或者 delete 对 benchmark 的影响，必要时使用预分配内存池

google benchmark

关于死锁

寻找死锁的原因

通过 gdb 可以找到对应 mutex 结构中的 owner，对应的值表示 LWP 的编号。
对于一些程序，可能 debug info 被优化掉了，此时可以选择：

1. 根据提示的行号，拷贝一份对应的源码到指定位置
2. 自己编译一个同样 layout 的对象，然后 load 进去解析

一些元工具

pstack

可以通过 https://gist.github.com/JaySon-Huang/e374da1fafa41a3fa30a24e135c60825 去合并相同的堆栈。

如果 pstack 没有安装，可以借助于 GDB 的 thread apply all bt 命令。但这个命令会对屏幕输入一堆字符，不是很好看。因此可以

set logging file mylog.txt
set logging on

或者使用命令行直接输出

gdb -ex "thread apply all bt" -batch -p $PID

perf_event 接口

https://man7.org/linux/man-pages/man2/perf_event_open.2.html

目前 glibc 库还没有封装这个接口，所以需要手动调用。

int syscall(SYS_perf_event_open, struct perf_event_attr *attr,
           pid_t pid, int cpu, int group_fd, unsigned long flags);

pid 和 cpu 可以指定需要追踪的 pid 和 cpu：

• pid 指定 0，表示要追踪的是调用者进程
• pid 指定 -1，表示追踪所有进程
• CPU 为 -1，表示追踪所有 CPU
• 其他情况下，都表示追踪某个特定的进程或者 cpu
• cpu 和 pid 不能同时为 -1

SIGPROF

SIGPROF 是一种用户级定时器信号，通过如下函数设置

setitimer(ITIMER_PROF, &interval, NULL);

缺点：

• 定时器分辨率受限（通常 1ms 左右）。
• 信号处理本身有开销，不适合高采样率。
• 在多线程程序中可能出现信号不精确的问题。

uprobe

func_latency 工具

这也是 bcc 套装里面的一个工具。

PT_PERF 技术

主要是看 mysql 内核月报 和续集学的，它还给了一个应用场景。
这个工具的原理是 Intel CPU 的 Processor Trace 技术。主要特点是开销小。它记录程序控制流，特别是 branch 跳转的信息。需要配合 pref 使用。

可以：

1. 跟踪某个函数在历史时间中执行时间的分布情况。
2. 跟踪该函数所有子函数的执行情况，包含各自花了多久，占比如何。
3. 跟踪 Off-CPU，参数 -o。
4. 通过 –history=1 记录，拷贝数据到另一台机器上通过 –history=2 分析。
5. 通过 -a do_command#67108864,134217727 指定对应父函数以及耗时范围，从而精准定位子函数存在的问题。

需要：

1. 修改 perf_event_mlock_kb 支持更大的 trace buffer，减少 trace 数据丢失。
2. 修改 kptr_restrict 支持追踪内核函数，如追踪 off-cpu 分析需要的 schedule 内核函数。

此外对 Linux 版本也有依赖。

eBPF 技术原理

包括 kprobe、uprobe、tcpdump 等工具都是基于 eBPF 技术实现的：

• kprobes：实现内核中动态跟踪。kprobes 可以跟踪到 Linux 内核中的导出函数入口或返回点，但是不是稳定 ABI 接口，可能会因为内核版本变化导致，导致跟踪失效。
• uprobes：用户级别的动态跟踪。与 kprobes 类似，只是跟踪用户程序中的函数。
• tracepoints：内核中静态跟踪。tracepoints 是内核开发人员维护的跟踪点，能够提供稳定的 ABI 接口，但是由于是研发人员维护，数量和场景可能受限。
• perf_events：定时采样和 PMC。

Reference

• https://www.brendangregg.com/blog/2017-05-09/cpu-utilization-is-wrong.html
• https://www.brendangregg.com/blog/2017-05-04/the-pmcs-of-ec2.html