利用perf剖析Linux应用程序
剖析(Profiling)是一种有效的、细粒度的软件性能检查手段,大部分编程语言的生态圈都有各种性能剖析工具。本文的讨论内容与具体编程语言无关,而关注在Linux系统上对应用程序的性能进行剖析。
Linux内核实现了非常有价值的性能分析基础设施(perf infrastructure),可以用于剖析各种CPU或软件事件。这一功能由perf_events接口暴露,并提供 perf这一用户空间工具,通过此工具,你可以发现以下问题的答案:
- 为什么内核使用太多的CPU,哪些代码使用了这些CPU时间
- 什么代码导致CPU二级缓存不命中
- CPU是否因内存IO而卡顿
- 什么代码在分配内存,分配了多少
- 什么触发了TCP重传
- 某个内核函数是否被频繁调用
- 线程离开CPU的原因
perf_events是内核2.6+的一部分,用户空间工具perf在包linux-tools-common中,需要安装才能使用。要想从剖析中获得更多内核相关信息,你需要符号(Symbol)和栈追踪,这可能需要安装额外的包,甚至使用特定选项重新编译你的内核。剖析用户空间代码时,也要求目标应用程序的调试信息(符号表)被保留。
perf_events有三种工作模式:
- counting,在内核上下文对各种指标进行计数
- sampling,对事件进行采样,并将性能数据存放到内核缓冲,然后异步的写入到perf.data
- bpf,4.4版本内核引入的新特性,允许在内核中执行一段用户自定义的代码,以执行高效的过滤、汇总
perf_events的采样是基于事件进行的。采样的周期以事件的数量来表示,而非基于时间。当目标事件计数溢出指定的数值,则产生一个采样。
样本中包含的信息取决于用户和工具指定的度量类型,但是最重要的信息是指令指针(instruction pointer),也就是程序被中断时所处的位置。
这种基于中断的采样,在现代处理器上存在刹车效应。也就是说,样本中记录的指针,和程序被中断以处理PMU事件时的指令指针,可能相隔数十个指令。
record子命令默认使用cycle事件,类似于定期采样。
perf_events可以捕获的事件类型包括:
- 硬件事件,来自CPU自己或CPU的PMU(Performance Monitoring Unit,性能监控单元),包含一系列微架构事件例如时钟周期、L1缓存丢失等。具体支持的事件类型取决于CPU型号
- 软件事件,基于内核计数器的低级事件,例如CPU迁移、上下文切换、Minor Faults、Major Faults(页面错误)
- 追踪点事件,由内核中的ftrace实现,包括:
- 内核追踪点事件,静态的、内核级的追踪点,硬编码到内核
- 用户静态定义追踪(USDT),用户态应用程序硬编码的追踪点
- 动态追踪,软件可以被动态instrumented,在任何位置创建事件。对于内核软件,使用kprobes框架,对于用户软件,使用uprobes
- 定时追踪,以任意频率抓取快照,主要用于CPU剖析,工作机制是定期引发中断
要启用内核动态追踪,需要使用内核编译参数CONFIG_KPROBES=y、CONFIG_KPROBE_EVENTS=y。要追踪基于帧指针的内核栈,需要内核编译参数CONFIG_FRAME_POINTER=y。
要启用用户动态追踪,需要使用内核编译参数CONFIG_UPROBES=y、CONFIG_UPROBE_EVENTS=y
事件有多种表示方式,最简单的是它的字符串表示。引用事件时,可以指定限定符:
1 2 3 4 5 |
# 剖析用户级、内核级的cycle事件 -e cycles -e cycles:uk # 仅用户级 -e cycles:u |
限定符包括:
限定符 | 说明 | 示例 |
u | 监控特权级别3, 2, 1 ,也就是用户态 | event:u |
k | 监控特权级别0,也就是内核态 | event:k |
h | 在虚拟化环境下监控Hypervisor事件 | event:h |
H | 在虚拟化环境下监控宿主机事件 | event:H |
G | 在虚拟化环境下监控客户机事件 | event:G |
perf可以在不同的范围收集性能数据:
- 单线程(per-thread):仅仅监控选择的线程。如果线程被调度失去CPU,对它的性能计数暂停,如果线程被调度到其它CPU,计数会存储并恢复,继续在新CPU上进行计数
- 单进程( per-process):进程的所有线程都被监控,计数被汇总
- 单CPU( per-cpu):仅仅监控单颗、或者选定的几颗CPU上的事件
- 全局(system-wide):监控所有CPU上的事件
和其它调试工具一样,perf需要符号信息,符号用于将内存地址转换为可读的函数、变量名称。没有符号信息,你会看到0x7ff3c1cddf29这样的HEX代码,无法阅读。
如果需要被剖析的软件通过包管理器安装,你需要找到并安装对应的调试包(可能以-dbgsym为后缀)。如果找不到调试包,可以考虑手工编译。
Java、Node.js等基于虚拟机的语言,在自己的虚拟CPU上执行代码,因而具有自己管理栈和执行函数的方法。
为了通过perf来剖析这类语言的程序,你需要:
- 对于Java,使用perf-map-agent
- 对于Node.js,使用命令行选项 --perf_basic_prof
你可能看不到完整的Java栈,这是因为X86上的Hotspot忽略了帧指针(Frame pointer)。在8u60+版本以后,可以使用-XX:+PreserveFramePointer修复这一问题。
为了方便剖析,编译时尽量保留帧指针,编译器的优化行为可能导致难以调试,但是很多情况下优化掉帧指针是默认行为。
缺少帧指针会导致无法看到完整的调用栈,解决此问题的方法有几种:
- 使用DWARF(ELF文件通常使用的调试信息格式)信息来Unwind栈
- 使用LBR(Last Branch Record),这是处理器特性,因此可能不可用
- 保留帧指针
下面是默认情况下编译(-O2,忽略帧指针)得到的OpenSSH的剖析结果:
1 2 3 4 5 6 7 8 9 10 11 |
57.14% sshd libc-2.15.so [.] connect | --- connect | |--25.00%-- 0x7ff3c1cddf29 | |--25.00%-- 0x7ff3bfe82761 | 0x7ff3bfe82b7c | |--25.00%-- 0x7ff3bfe82dfc --25.00%-- [...] |
以 -fno-omit-frame-pointer重新编译后:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
100.00% sshd libc-2.15.so [.] __GI___connect_internal | --- __GI___connect_internal | |--30.00%-- add_one_listen_addr.isra.0 | add_listen_addr | fill_default_server_options | main | __libc_start_main | |--20.00%-- __nscd_get_mapping | __nscd_get_map_ref | |--20.00%-- __nscd_open_socket --30.00%-- [...] |
可以看到符号都显示出来了,另外add_one_listen_addr的祖先帧也显示出来了。
你需要使用 CONFIG_FRAME_POINTER=y来编译内核,以保留栈指针信息。
从内核3.9版本开始,缺失栈指针的问题有个变通的解决方案(对于用户空间的栈)——使用libunwind。libunwind基于dwarf,调用perf时传入--call-graph dwarf即可。
在Ubuntu上可以这样安装:
1 |
apt install linux-tools-common |
系统可能会提示你安装其它的包,安装即可。
perf支持一系列的子命令:
子命令 | 说明 |
annotate | 读取perf.data并显示被注解的代码 |
bench | 基准测试的框架 |
config | 在配置文件中读写配置项 |
diff | 读取perf.data并显示剖析差异 |
evlist | 列出perf.data中的事件名称 |
inject | 用于增强事件流的过滤器 |
kmem | 跟踪/度量内核内存属性 |
kvm | 跟踪/度量KVM客户机系统 |
list | 显示符号化的事件列表 |
lock | 分析锁事件 |
mem | 分析内存访问 |
record | 执行剖析 |
report | 显示剖析结果 |
sched | 分析调度器 |
stat | 获取性能计数 |
top | 显示成本最高的操作并动态刷新 |
trace | 类似于strace的工具 |
probe | 定义新的动态追踪点 |
运行一个命令,并收集性能计数器。
对于任何支持计数的事件,perf都能够在进程执行期间对发生的事件进行计数,计数结果会直接打印在控制台上。
stat子命令可以在线程、进程、CPU、全局级别进行计数。默认情况下进程的所有线程、子进程的计数都被统计在内,可以通过-i选项修改此行为。
参考record子命令。
1 2 3 |
# 如果不指定-e,则默认收集所有事件的计数器 perf stat [-e <EVENT> | --event=EVENT] [-a] <command> perf stat [-e <EVENT> | --event=EVENT] [-a] -- <command> [<options>] |
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 |
# CPU性能计数器 perf stat command # 详细的CPU性能计数器 perf stat -d command # 收集指定进程的性能计数,直到Ctrl-C perf stat -p PID # 收集整个系统的性能计数,持续5秒 perf stat -a sleep 5 # Performance counter stats for 'system wide': # 20010.623960 cpu-clock (msec) # 4.000 CPUs utilized # 61,947 context-switches # 0.003 M/sec # 4,153 cpu-migrations # 0.208 K/sec # 99 page-faults # 0.005 K/sec # 5,003,068,069 cycles # 0.250 GHz (49.96%) # 2,000,087,622 instructions # 0.40 insn per cycle (75.00%) # 393,183,513 branches # 19.649 M/sec (75.05%) # 24,391,051 branch-misses # 6.20% of all branches (74.99%) # 5.003219775 seconds time elapsed # 指定需要收集的几种计数器,持续10秒 perf stat -e cycles,instructions,cache-references,cache-misses,bus-cycles -a sleep 10 # CPU一级缓存计数器 perf stat -e L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores command # TLB计数器 perf stat -e dTLB-loads,dTLB-load-misses,dTLB-prefetch-misses command # CPU最后一级缓存计数器 perf stat -e LLC-loads,LLC-load-misses,LLC-stores,LLC-prefetches command # 统计指定进程的系统调用 perf stat -e 'syscalls:sys_enter_*' -p PID # 统计全局系统调用 perf stat -e 'syscalls:sys_enter_*' -a sleep 5 # 统计调度器相关事件 perf stat -e 'sched:*' -p PID perf stat -e 'sched:*' -p PID sleep 10 # 统计Ext4相关事件 perf stat -e 'ext4:*' -a sleep 10 # 统计块IO事件 perf stat -e 'block:*' -a sleep 10 # 收集多种事件 perf stat -e cycles,instructions,cache-misses |
动态显示执行成本最高的项。
默认情况下以cycles事件采样,样本最高的输出在最顶部。
1 2 3 4 |
# 动态显示成本最高的地址和符号,不保存到文件 perf top -F 49 # 动态显示成本最高的命令 perf top -F 49 -ns comm,dso |
此命令可以启动一个命令,并对其进行剖析,然后把剖析数据记录到文件(默认perf.data)。按Ctrl - C可以随时结束剖析。
此命令可以在线程、进程、CPU、全局级别进行剖析。
record, report, annotate是一组相关的命名,通常的使用流程是:
- 在被剖析机器上调用record录制数据
- 拷贝录制的perf.data,在任意机器上调用report、annotate进行分析
该命令不是记录所有事件,还是进行采样。默认情况下采样基于cycle事件,也就是进行定期采样。
perf_events接口允许通过两种方式描述采样周期:
- period:事件发生的次数
- frequency:每秒样本的平均个数
perf默认使用第二种,具体来说对应到-F选项。-F 1000表示1000Hz,也就是每秒平均采样1000个。内核会动态的调整采样周期,以尽量满足需求。
1 2 |
perf record [-e <EVENT> | --event=EVENT] [-l] [-a] <command> perf record [-e <EVENT> | --event=EVENT] [-l] [-a] -- <command> [<options>] |
选项 | 说明 |
-e |
剖析的事件类型,也就是性能监控单元(Performance Monitoring Unit,PMU)类型。可以指定:
|
--filter | 事件过滤器,必须和指定了追踪点(tracepoint)事件的-e配合使用 |
--exclude-perf | 不记录perf自己发起的事件 |
-a |
使用Per-CPU模式,如果不指定-C,则相当于全局模式 如果指定-C,则可以选定若干CPU |
-p | 收集指定进程的事件,逗号分割的PID列表 |
-t | 收集指定线程的事件,逗号分割的线程ID列表 |
-u | 收集指定用户的进程的事件 |
-r | 使用RT SCHED_FIFO优先级收集数据 |
-c | 采样周期 |
-o | 输出文件的名称 |
-i | 不包括子任务的事件,不监控子进程、线程、子进程的线程 |
-F | 以指定的频率剖析 |
-g | 记录调用栈 |
--call-graph |
收集调用栈使用的方法:
某些系统上,如果应用通过GCC的--fomit-frame-pointer参数构建,fp模式下可能只能看到匿名调用帧,可以用dwarf代替 |
-s | 记录每个线程的事件计数器,配合 perf report -T使用 |
-d | 记录样本地址 |
-T | 记录样本时间戳 |
-P | 记录样本周期 |
-C | 仅仅从指定的CPU上收集样本,示例: -C 0,2-3 |
-G | 仅仅记录指定控制组的事件 |
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 |
# 以99HZ的频率剖析指定的命令,默认情况下工作在Per-thread模式 perf record -F 99 command # 以99HZ的频率剖析指定的PID perf record -F 99 -p PID # 以99HZ的频率剖析指定的PID,持续10秒 perf record -F 99 -p PID sleep 10 # 以99HZ的频率剖析整个系统 perf record -F 99 -ag -- sleep 10 # 基于事件发生次数,而非采样频率来指定采样周期 perf record -e retired_instructions:u -c 2000 # 进行栈追踪(通过Frame Pointer) perf record -F 99 -p PID -g -- sleep 10 # 进行栈追踪(通过DWARF) perf record -F 99 -p PID --call-graph dwarf sleep 10 # 全局性栈追踪 perf record -F 99 -ag -- sleep 10 # 4.11之前 perf record -F 99 -g -- sleep 10 # 4.11之后 # 追踪某个容器的栈 perf record -F 99 -e cpu-clock --cgroup=docker/1d567f4393190204...etc... -a -- sleep 10 # 每发生10000次L1缓存丢失,进行一次采样 perf record -e L1-dcache-load-misses -c 10000 -ag -- sleep 5 # 每发生以100次最后级别的CPU缓存丢失,进行一次采用 perf record -e LLC-load-misses -c 100 -ag -- sleep 5 # 采样内核指令 perf record -e cycles:k -a -- sleep 5 # 采用用户指令 perf record -e cycles:u -a -- sleep 5 # 精确采样用户指令,基于PEBS perf record -e cycles:up -a -- sleep 5 |
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 |
# 追踪新进程的创建 perf record -e sched:sched_process_exec -a # 追踪上下文切换 perf record -e context-switches -a perf record -e context-switches -c 1 -a perf record -e context-switches -ag # 追踪通过sched跟踪点的上下文切换 perf record -e sched:sched_switch -a # 追踪CPU迁移 perf record -e migrations -a -- sleep 10 # 追踪所有connect调用(出站连接) perf record -e syscalls:sys_enter_connect -ag # 追踪所有accepts调用(入站连接) perf record -e syscalls:sys_enter_accept* -ag # 追踪所有块设备请求 perf record -e block:block_rq_insert -ag # 追踪所有块设备发起和完成 perf record -e block:block_rq_issue -e block:block_rq_complete -a # 追踪100KB(200扇区)以上的块操作完成 perf record -e block:block_rq_complete --filter 'nr_sector > 200' # 追踪所有同步写操作的完成 perf record -e block:block_rq_complete --filter 'rwbs == "WS"' # 追踪所有写操作的完成 perf record -e block:block_rq_complete --filter 'rwbs ~ "*W*"' # 采样Minor faults(RSS尺寸增加) perf record -e minor-faults -ag perf record -e minor-faults -c 1 -ag # 采样页面错误 perf record -e page-faults -ag # 追踪所有Ext4调用,并把结果写入到非Ext4分区 perf record -e 'ext4:*' -o /tmp/perf.data -a # 追踪kswapd唤醒事件 perf record -e vmscan:mm_vmscan_wakeup_kswapd -ag # 添加Node.js USDT 探针,要求Linux 4.10+ perf buildid-cache --add `which node` # 跟踪Node.js http__server__request USDT事件 perf record -e sdt_node:http__server__request -a |
此命令用于分析perf record生成的perf.data文件。
1 |
perf report [-i <file> | --input=file] |
选项 | 说明 |
-i | 指定输入文件 |
-n | 显示每个符号的样本数量 |
-T | 显示每个线程的事件计数器 |
--pid | 仅仅显示指定PID的事件 |
--tid | 仅仅显示指定TID的事件 |
-s |
指定直方图的排序方式,逗号分隔多个排序方式,优先级降序 comm 任务的命令 |
-F | 指定输出字段,逗号分隔多个字段 |
默认情况下,样本根据函数(符号)分类,数量最多的样本位于最前面:
1 2 3 4 5 6 7 8 9 10 |
# Overhead Command Shared Object Symbol + 21.70% swapper [kernel.kallsyms] [k] 0xffffffff8104f45a + 8.89% qemu-system-x86 [kernel.kallsyms] [k] 0xffffffff810496f6 + 3.32% Xorg [kernel.kallsyms] [k] 0xffffffff8172da33 + 2.96% vmware-vmx [kernel.kallsyms] [k] 0xffffffff81121880 + 2.23% chrome chrome [.] 0x0000000004fdb6e6 + 2.17% java [kernel.kallsyms] [k] 0xffffffff8109f02b + 1.71% chrome [kernel.kallsyms] [k] 0xffffffff8172d982 + 1.56% Xorg [nvidia] [k] _nv008054rm + 1.55% Xorg [nvidia] [k] _nv014095rm |
各列含义如下:
- Overhead,在对应函数中采样到的样本计数
- Command,样本从什么应用程序中采集到
- Shared Object,样本来自的ELF镜像。如果:
- 应用程序是动态链接的,这里可能显示共享库的名称
- 如果样本来自内核空间,则一律显示伪ELF镜像名“kernel.kallsyms”
- 第4列是特权级别,点号表示用户级别,k、g、u、H分别表示内核级别、客户机内核级别、客户机用户级别、hypervisor
- 最后一列是符号名称,如果缺乏调试信息,则显示为0x开头的函数内存地址
你可以指定多种分组规则,对样本数进行统计。
下面的例子根据共享对象分组:
1 2 3 4 5 6 7 8 |
perf report --sort=dso + 48.05% [kernel.kallsyms] + 8.06% libglib-2.0.so.0.4600.1 + 5.81% libc-2.19.so + 4.93% [nvidia] + 2.83% libgobject-2.0.so.0.4600.1 + 2.39% [kvm_intel] |
下面的例子根据CPU序号分组:
1 2 3 4 5 6 7 8 9 10 |
perf report --sort=cpu + 17.10% 0 + 15.21% 2 + 14.76% 4 + 12.81% 6 + 11.98% 3 + 10.00% 5 + 9.85% 1 + 8.28% 7 |
perf不知道如何从压缩内核(vmlinuz)中抽取符号,如果你的内核保留了调试符号,则可以用-k来指出未压缩内核的位置:
1 |
perf report -k /tmp/vmlinux |
如果在record时收集了调用链,则Overhead可以在Children、Self两个列中显示。Children显示子代函数的样本计数、Self显示函数自己的样本计数
1 2 3 4 5 6 7 8 9 10 |
# 报告perf.data perf report # 显示样本数量 perf report -n # 树状结构显示,展开,可以追踪到高成本的执行路径 perf report --stdio # 每行显示一个帧,扁平化显示,按成本降序排列 perf report --stdio -n -g folded |
此命令用于源码级别的分析。
所有被采样到的函数都会被反汇编,每个指令占据采样的比例会被输出。
如果应用程序以-ggdb编译,annotate还能够生成源码级别信息:
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 |
------------------------------------------------ Percent | Source code & Disassembly of noploop ------------------------------------------------ : : : : Disassembly of section .text: : : 08048484 <main>: : #include <string.h> : #include <unistd.h> : #include <sys/time.h> : : int main(int argc, char **argv) : { 0.00 : 8048484: 55 push %ebp 0.00 : 8048485: 89 e5 mov %esp,%ebp [...] 0.00 : 8048530: eb 0b jmp 804853d <main+0xb9> : count++; 14.22 : 8048532: 8b 44 24 2c mov 0x2c(%esp),%eax 0.00 : 8048536: 83 c0 01 add $0x1,%eax 14.78 : 8048539: 89 44 24 2c mov %eax,0x2c(%esp) : memcpy(&tv_end, &tv_now, sizeof(tv_now)); : tv_end.tv_sec += strtol(argv[1], NULL, 10); : while (tv_now.tv_sec < tv_end.tv_sec || : tv_now.tv_usec < tv_end.tv_usec) { : count = 0; : while (count < 100000000UL) 14.78 : 804853d: 8b 44 24 2c mov 0x2c(%esp),%eax 56.23 : 8048541: 3d ff e0 f5 05 cmp $0x5f5e0ff,%eax 0.00 : 8048546: 76 ea jbe 8048532 <main+0xae> [...] |
再次强调一下刹车现象,百分比信息可能不准确。
对于压缩内核,你可以指定非压缩版本内核的位置,以解析符号:
1 |
perf annotate -k /tmp/vmlinux -d symbol |
显示支持的事件列表。
1 2 3 4 5 |
# 显示所有事件 perf list # 显示跟踪点sched下的事件 perf list 'sched:*' |
用于定义新的追踪点,实现动态追踪。
1 2 3 4 5 6 7 |
perf probe [options] --add=PROBE [...] perf probe [options] PROBE perf probe [options] --del=[GROUP:]EVENT [...] perf probe --list[=[GROUP:]EVENT] perf probe [options] --line=LINE perf probe [options] --vars=PROBEPOINT perf probe [options] --funcs |
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 |
# 为tcp_sendmsg函数添加进入追踪点,--add可以省略 perf probe --add tcp_sendmsg # 移除tcp_sendmsg进入追踪点 perf probe -d tcp_sendmsg # 为tcp_sendmsg函数添加退出追踪点 perf probe 'tcp_sendmsg%return' # 显示tcp_sendmsg的可用变量,需要debuginfo perf probe -V tcp_sendmsg # 显示tcp_sendmsg的可用变量和外部变量 perf probe -V tcp_sendmsg --externs # 显示tcp_sendmsg可用的行探针 perf probe -L tcp_sendmsg # 显示tcp_sendmsg的81行可用的探针 perf probe -V tcp_sendmsg:81 # 为tcp_sendmsg添加进入进入追踪点,使用3个参数寄存器(依赖于平台) perf probe 'tcp_sendmsg %ax %dx %cx' # 为tcp_sendmsg添加进入进入追踪点,且将cx寄存器设置别名bytes(依赖于平台) perf probe 'tcp_sendmsg bytes=%cx' # 追踪tcp_sendmsg,要求%cx变量大于100 perf record -e probe:tcp_sendmsg --filter 'bytes > 100' # 捕获返回值 perf probe 'tcp_sendmsg%return $retval' # 为tcp_sendmsg和它的入口参数size添加追踪点,需要debuginfo,但是不依赖平台 perf probe 'tcp_sendmsg size' # 为tcp_sendmsg和size、Socket状态添加追踪点 perf probe 'tcp_sendmsg size sk->__sk_common.skc_state' # size大于0并且套接字状态不为TCP_ESTABLISHED时追踪tcp_sendmsg perf record -e probe:tcp_sendmsg --filter 'size > 0 && skc_state != 1' -a # 在tcp_sendmsg的81行添加追踪点,使用局部变量seglen perf probe 'tcp_sendmsg:81 seglen' # 为libc的用户态malloc函数添加探针 perf probe -x /lib64/libc.so.6 malloc # 列出可用的动态探针 perf probe -l? |
该命令使用额外的信息来增强事件流。
选项 | 说明 |
-b | 注入build-ids |
-v | 冗长输出 |
-i | 指定输入文件 |
-o | 指定输出文件 |
-s | 合并sched_stat、sched_switch,以获得任务在何处睡眠、睡眠了多久 |
进行10秒钟的剖析:
1 |
perf record -a -g sleep 10 |
根据应用程序的名称进行分组,整体上根据样本的执行成本进行排序:
1 |
perf report --sort comm,dso |
可以展开执行成本高的项,追踪到CPU时间都消耗在哪里了:
对于上面这个例子,可以看到,kubelet消耗的资源主要用于Prometheus相关的指标收集,以及grpc的客户端。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
perf stat -- tar xzf ideaIU-2018.3.3.tar.gz Performance counter stats for 'tar xzf ideaIU-2018.3.3.tar.gz': # 反映CPU利用率 9725.627068 task-clock (msec) # 0.941 CPUs utilized # 上下文切换数量 45,568 context-switches # 0.005 M/sec 1,370 cpu-migrations # 0.141 K/sec # 页面错误数量 623 page-faults # 0.064 K/sec # 经过的时钟周期的数量 36,249,427,884 cycles # 3.727 GHz # IPC,每时钟周期指令数(instructions per cycle),通常越高越好,表示工作处理过程是优化的 # 但是,最好还是检查实际执行的指令,Spin loop就是高指令频率但是实际上什么事都不做的反例 46,378,956,536 instructions # 1.28 insns per cycle # 分支和分支预测失败 8,274,686,762 branches # 850.813 M/sec 214,332,307 branch-misses # 2.59% of all branches 10.334029429 seconds time elapsed |
perf_events支持使用固定频率来采样指令指针或栈追踪,进而分析CPU使用。采样频率通过-F选项指定。
频率可以选用99,而非100HZ,以避免采样和某些周期性活动的步调完全一致而导致结果失真。如果需要更高分辨率的采样,可以使用997这样的频率,但是注意频率越高剖析本身的成本也越高。
示例:
1 2 |
# 以99HZ频率,全局的采样30秒 perf record -F 99 -a -g -- sleep 30 |
除了定时触发(固定频率采样),采样也可以由特定的CPU硬件计数器触发。使用这些计数器可以分析缓存丢失、memory stall cycles(由于访问内存而导致的时钟周期浪费,内存访问速度相对CPU时钟周期要慢的多)等更低级别的处理器事件。
可用的事件列表:
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 |
perf list | grep Hardware cpu-cycles OR cycles [Hardware event] instructions [Hardware event] cache-references [Hardware event] cache-misses [Hardware event] branch-instructions OR branches [Hardware event] branch-misses [Hardware event] bus-cycles [Hardware event] ref-cycles [Hardware event] L1-dcache-loads [Hardware cache event] L1-dcache-load-misses [Hardware cache event] L1-dcache-stores [Hardware cache event] L1-dcache-store-misses [Hardware cache event] L1-dcache-prefetch-misses [Hardware cache event] L1-icache-load-misses [Hardware cache event] LLC-loads [Hardware cache event] LLC-stores [Hardware cache event] LLC-prefetches [Hardware cache event] dTLB-loads [Hardware cache event] dTLB-load-misses [Hardware cache event] dTLB-stores [Hardware cache event] dTLB-store-misses [Hardware cache event] iTLB-loads [Hardware cache event] iTLB-load-misses [Hardware cache event] branch-loads [Hardware cache event] branch-load-misses [Hardware cache event] mem:<addr>[:access] [Hardware breakpoint] |
如果每当发生这些事件,就记录栈追踪,对系统性能有严重的影响。因此,通常使用-c选项,当计数器增加一定数量后,记录一次栈追踪:
1 |
perf record -e L1-dcache-load-misses -c 10000 -ag -- sleep 5 |
上面这个例子,每当L1缓存丢失10000次,记录一次栈追踪。
下面的命令统计所有调用次数大于0的系统调用的数量:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
perf stat -e 'syscalls:sys_enter_*' tar xzf ideaIU-2018.3.3.tar.gz 2>&1 | awk '$1 != 0' Performance counter stats for 'tar xzf ideaIU-2018.3.3.tar.gz': 2 syscalls:sys_enter_statfs 12,417 syscalls:sys_enter_utimensat ... 12,417 syscalls:sys_enter_unlinkat ... 12,432 syscalls:sys_enter_newfstat 1 syscalls:sys_enter_lseek 184,818 syscalls:sys_enter_read 192,154 syscalls:sys_enter_write 12 syscalls:sys_enter_access 12,417 syscalls:sys_enter_fchmod 12,417 syscalls:sys_enter_fchown 26 syscalls:sys_enter_open 24,834 syscalls:sys_enter_openat 12,442 syscalls:sys_enter_close ... 38.365080478 seconds time elapsed |
可以看到,主要的系统调用都是read/write。
使用strace命令可以获得类似的结果,但是strace的成本要高的多。测试结果显示,perf可能让程序变慢2.5倍,而strace则会让程序变慢高达60倍。
1 2 3 4 5 6 7 8 9 10 11 12 |
perf record -e sched:sched_process_exec -a # Ctrl-C perf report -n --sort comm --stdio # Overhead Samples Command # ........ ............ ....... # 32.14% 9 ionice 32.14% 9 nice 21.43% 6 du 10.71% 3 find 3.57% 1 ipset |
追踪点sched:sched_process_exec在某个进程调用exec()产生另外一个进程时生效,这通常是新进程的产生方式。但是这个例子的结果不一定准确,原因是:
- 进程可能fork()出子进程,追踪点sched:sched_process_fork可以用于这种情况
- 应用程序可以reexec —— 针对自己再次调用exec() —— 这种用法可以清空地址空间,但是不会产生新进程
某些时候你希望了解服务器发起了哪些网络连接,是哪些进程发起的,为何发起。这些网络连接可能是延迟的根源。
追踪connect系统调用,即可了解出站连接:
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 |
perf record -e syscalls:sys_enter_connect -ag perf report --stdio # Children Self Trace output # ........ ........ ............................................................ # 5.88% 5.88% fd: 0x00000005, uservaddr: 0xc4206fa390, addrlen: 0x0000001b | ---0x894812ebc0312874 0xc42008e000 runtime.main main.main github.com/projectcalico/node/pkg/readiness.Run github.com/projectcalico/node/pkg/readiness.checkBIRDReady github.com/projectcalico/node/pkg/readiness/bird.GRInProgress net.Dial net.(*Dialer).Dial net.(*Dialer).DialContext net.dialSerial net.dialSingle net.dialUnix net.unixSocket net.socket net.(*netFD).dial net.(*netFD).connect syscall.Connect syscall.Syscall |
可以看到,占比最高的出站连接是由Calico Node容器发起的。
通过剖析套接字缓冲的使用情况,也是定位到什么代码使用了最多的网络I/O的一种方法:
1 |
perf record -e 'skb:consume_skb' -ag |
使用perf可以了解应用程序为何休眠、在何处休眠、休眠多久。主要通过收集sched_stat、sched_switch事件实现。
剖析的目标代码如下:
1 2 3 4 5 6 7 8 9 10 11 |
for (i = 0; i < 10; i++) { ts1.tv_sec = 0; ts1.tv_nsec = 10000000; // 休眠 nanosleep(&ts1, NULL); tv1.tv_sec = 0; tv1.tv_usec = 40000; // 休眠 select(0, NULL, NULL, NULL,&tv1); } |
执行下面的命令开始剖析:
1 |
./perf record -e sched:sched_stat_sleep -e sched:sched_switch -e sched:sched_process_exit -g -o perf.data.raw sleep_test |
合并sched_start、sched_switch事件:
1 |
perf inject -v -s -i perf.data.raw -o perf.data |
报告:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
perf report --stdio --show-total-period -i perf.data 100.00% 502408738 foo [kernel.kallsyms] [k] __schedule | --- __schedule schedule | |--79.85%-- schedule_hrtimeout_range_clock | schedule_hrtimeout_range | poll_schedule_timeout | do_select | core_sys_select | sys_select | system_call_fastpath | __select | __libc_start_main | --20.15%-- do_nanosleep hrtimer_nanosleep sys_nanosleep system_call_fastpath __GI___libc_nanosleep __libc_start_main |
Leave a Reply