系统级性能分析工具perf的介绍与使用[转]
测试环境：Ubuntu16.04（在VMWare虚拟机使用perf top存在无法显示问题）
Kernel：3.13.0-32
系统级性能优化通常包括两个阶段：性能剖析（performance profiling）和代码优化。性能剖析的目标是寻找性能瓶颈，查找引发性能问题的原因及热点代码。代码优化的目标是针对具体性能问题而优化代码或编译选项，以改善软件性能。
在性能剖析阶段，需要借助于现有的profiling工具，如perf等。在代码优化阶段往往需要借助开发者的经验，编写简洁高效的代码，甚至在汇编级别合理使用各种指令，合理安排各种指令的执行顺序。
perf是一款Linux性能分析工具。Linux性能计数器是一个新的基于内核的子系统，它提供一个性能分析框架，比如硬件（CPU、PMU(Performance Monitoring Unit)）功能和软件(软件计数器、tracepoint)功能。
通过perf，应用程序可以利用PMU、tracepoint和内核中的计数器来进行性能统计。它不但可以分析制定应用程序的性能问题（per thread），也可以用来分析内核的性能问题，当然也可以同事分析应用程序和内核，从而全面理解应用程序中的性能瓶颈。
使用perf，可以分析程序运行期间发生的硬件事件，比如instructions retired、processor clock cycles等；也可以分析软件时间，比如page fault和进程切换。
背景知识
tracepoints
tracepoints是散落在内核源码中的一些hook，它们可以在特定的代码被执行到时触发，这一特定可以被各种trace/debug工具所使用。
perf将tracepoint产生的时间记录下来，生成报告，通过分析这些报告，条有人缘便可以了解程序运行期间内核的各种细节，对性能症状做出准确的诊断。
硬件特性之cache
内存读写是很快的，但是还是无法和处理器指令执行速度相比。为了从内存中读取指令和数据，处理器需要等待，用处理器时间来衡量，这种等待非常漫长。cache是一种SRAM，读写速度非常快，能和处理器相匹配。因此将常用的数据保存在cache中，处理器便无需等待，从而提高性能。cache的尺寸一般都很小，充分利用cache是软件调优非常重要部分。
主要关注点
基于性能分析，可以进行算法优化（空间复杂度和时间复杂度权衡）、代码优化（提高执行速度、减少内存占用）。
评估程序对硬件资源的使用情况，例如各级cache的访问次数、各级cache的丢失次数、流水线停顿周期、前端总线访问次数等。
评估程序对操作系统资源的使用情况，系统调用次数、上下文切换次数、任务迁移次数。
事件可以分为三种：
- Hardware Event由PMU部件产生，在特定的条件下探测性能事件是否发生以及发生的次数。比如cache命中。
- Software Event是内核产生的事件，分布在各个功能模块中，统计和操作系统相关性能事件。比如进程切换，tick数等。
-
Tracepoint Event是内核中静态tracepoint所触发的事件，这些tracepoint用来判断程序运行期间内核的行为细节，比如slab分配器的分配次数等。
perf的使用
perf --help之后可以看到perf的二级命令。
| 序号 | 命令 | 作用 |
| 1 | annotate | 解析perf record生成的perf.data文件，显示被注释的代码。 |
| 2 | archive | 根据数据文件记录的build-id，将所有被采样到的elf文件打包。利用此压缩包，可以再任何机器上分析数据文件中记录的采样数据。 |
| 3 | bench | perf中内置的benchmark，目前包括两套针对调度器和内存管理子系统的benchmark。 |
| 4 | buildid-cache | 管理perf的buildid缓存，每个elf文件都有一个独一无二的buildid。buildid被perf用来关联性能数据与elf文件。 |
| 5 | buildid-list | 列出数据文件中记录的所有buildid。 |
| 6 | diff | 对比两个数据文件的差异。能够给出每个符号（函数）在热点分析上的具体差异。 |
| 7 | evlist | 列出数据文件perf.data中所有性能事件。 |
| 8 | inject | 该工具读取perf record工具记录的事件流，并将其定向到标准输出。在被分析代码中的任何一点，都可以向事件流中注入其它事件。 |
| 9 | kmem | 针对内核内存（slab）子系统进行追踪测量的工具 |
| 10 | kvm | 用来追踪测试运行在KVM虚拟机上的Guest OS。 |
| 11 | list | 列出当前系统支持的所有性能事件。包括硬件性能事件、软件性能事件以及检查点。 |
| 12 | lock | 分析内核中的锁信息，包括锁的争用情况，等待延迟等。 |
| 13 | mem | 内存存取情况 |
| 14 | record | 收集采样信息，并将其记录在数据文件中。随后可通过其它工具对数据文件进行分析。 |
| 15 | report | 读取perf record创建的数据文件，并给出热点分析结果。 |
| 16 | sched | 针对调度器子系统的分析工具。 |
| 17 | script | 执行perl或python写的功能扩展脚本、生成脚本框架、读取数据文件中的数据信息等。 |
| 18 | stat | 执行某个命令，收集特定进程的性能概况，包括CPI、Cache丢失率等。 |
| 19 | test | perf对当前软硬件平台进行健全性测试，可用此工具测试当前的软硬件平台是否能支持perf的所有功能。 |
| 20 | timechart | 针对测试期间系统行为进行可视化的工具 |
| 21 | top | 类似于linux的top命令，对系统性能进行实时分析。 |
| 22 | trace | 关于syscall的工具。 |
| 23 | probe | 用于定义动态检查点。 |
下面开始逐一分析。
perf list
perf list不能完全显示所有支持的事件类型，需要sudo perf list。
同时还可以显示特定模块支持的perf事件,hw/cache/pmu都是硬件相关的；tracepoint基于内核的ftrace；sw实际上是内核计数器。
hw/hardware显示支持的硬件事件相关，如：
|
al@ubuntu:~/common-use/example/perf-test$ perf list hardware |
sw/software显示支持的软件事件列表：
|
al@ubuntu:~/common-use/example/perf-test$ perf list sw |
cache/hwcache显示硬件cache相关事件列表：
|
al@ubuntu:~/common-use/example/perf-test$ perf list cache |
pmu显示支持的PMU事件列表：
|
al@ubuntu:~/common-use/example/perf-test$ perf list pmu |
tracepoint显示支持的所有tracepoint列表，这个列表就比较庞大：
|
drm:drm_vblank_event [Tracepoint event] |
perf top
默认情况下perf top是无法显示信息的，需要sudo perf top或者echo -1 > /proc/sys/kernel/perf_event_paranoid(在Ubuntu16.04，还需要echo 0 > /proc/sys/kernel/kptr_restrict)。
即可以正常显示perf top如下：
第一列：符号引发的性能事件的比例，指占用的cpu周期比例。
第二列：符号所在的DSO(Dynamic Shared Object)，可以是应用程序、内核、动态链接库、模块。
第三列：DSO的类型。[.]表示此符号属于用户态的ELF文件，包括可执行文件与动态链接库)。[k]表述此符号属于内核或模块。
第四列：符号名。有些符号不能解析为函数名，只能用地址表示。
关于perf top界面常用命令如下：
h：显示帮助，即可显示详细的帮助信息。
UP/DOWN/PGUP/PGDN/SPACE：上下和翻页。
a：annotate current symbol，注解当前符号。能够给出汇编语言的注解，给出各条指令的采样率。
d：过滤掉所有不属于此DSO的符号。非常方便查看同一类别的符号。
P：将当前信息保存到perf.hist.N中。
perf top常用选项有：
-e <event>：指明要分析的性能事件。
-p <pid>：Profile events on existing Process ID (comma sperated list). 仅分析目标进程及其创建的线程。
-k <path>：Path to vmlinux. Required for annotation functionality. 带符号表的内核映像所在的路径。
-K：不显示属于内核或模块的符号。
-U：不显示属于用户态程序的符号。
-d <n>：界面的刷新周期，默认为2s，因为perf top默认每2s从mmap的内存区域读取一次性能数据。
-g：得到函数的调用关系图。
perf top -g [fractal]，路径概率为相对值，加起来为100%，调用顺序为从下往上。
perf top -g graph，路径概率为绝对值，加起来为该函数的热度。
perf stat
perf stat用于运行指令，并分析其统计结果。虽然perf top也可以指定pid，但是必须先启动应用才能查看信息。
perf stat能完整统计应用整个生命周期的信息。
命令格式为：
|
perf stat [-e <EVENT> | --event=EVENT] [-a] <command> |
下面简单看一下perf stat ls的输出：
| Performance counter stats for 'ls': 1.051536 task-clock (msec) # 0.670 CPUs utilized 0 context-switches # 0.000 K/sec 0 cpu-migrations # 0.000 K/sec 93 page-faults # 0.088 M/sec 1,942,492 cycles # 1.847 GHz 532,500 stalled-cycles-frontend # 27.41% frontend cycles idle 724,600 stalled-cycles-backend # 37.30% backend cycles idle <not counted> instructions (0.00%) <not counted> branches (0.00%) <not counted> branch-misses (0.00%) 0.001569326 seconds time elapsed |
task-clock：任务真正占用的处理器时间，单位为ms。CPUs utilized = task-clock / time elapsed，CPU的占用率。
context-switches：程序在运行过程中上下文的切换次数。
CPU-migrations：程序在运行过程中发生的处理器迁移次数。Linux为了维持多个处理器的负载均衡，在特定条件下会将某个任务从一个CPU迁移到另一个CPU。
CPU迁移和上下文切换：发生上下文切换不一定会发生CPU迁移，而发生CPU迁移时肯定会发生上下文切换。发生上下文切换有可能只是把上下文从当前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是预测错误的分支指令数。
其他常用参数
-a, --all-cpus 显示所有CPU上的统计信息
-C, --cpu <cpu> 显示指定CPU的统计信息
-c, --scale scale/normalize counters
-D, --delay <n> ms to wait before starting measurement after program start
-d, --detailed detailed run - start a lot of events
-e, --event <event> event selector. use 'perf list' to list available events
-G, --cgroup <name> monitor event in cgroup name only
-g, --group put the counters into a counter group
-I, --interval-print <n>
print counts at regular interval in ms (>= 10)
-i, --no-inherit child tasks do not inherit counters
-n, --null null run - dont start any counters
-o, --output <file> 输出统计信息到文件
-p, --pid <pid> stat events on existing process id
-r, --repeat <n> repeat command and print average + stddev (max: 100, forever: 0)
-S, --sync call sync() before starting a run
-t, --tid <tid> stat events on existing thread id
-T, --transaction hardware transaction statistics
-v, --verbose be more verbose (show counter open errors, etc)
-x, --field-separator <separator>
print counts with custom separator
--append append to the output file
--filter <filter>
event filter
--log-fd <n> log output to fd, instead of stderr
--per-core aggregate counts per physical processor core
--per-socket aggregate counts per processor socket
--per-thread aggregate counts per thread
--post <command> 执行待测程序前执行的程序
--pre <command> 执行待测程序后执行的程序
示例
前面统计程序的示例，下面看一下统计CPU信息的示例：
执行sudo perf stat -C 0，统计CPU 0的信息。想要停止后，按下Ctrl+C终止。可以看到统计项一样，只是统计对象变了。
| Performance counter stats for 'CPU(s) 0': 10164.997531 task-clock (msec) # 1.000 CPUs utilized (100.00%) 1,147 context-switches # 0.113 K/sec (100.00%) 62 cpu-migrations # 0.006 K/sec (100.00%) 76 page-faults # 0.007 K/sec 353,147,998 cycles # 0.035 GHz (49.97%) 55,541,309 stalled-cycles-frontend # 15.73% frontend cycles idle (50.00%) 1,163,503,673 stalled-cycles-backend # 329.47% backend cycles idle (50.04%) 51,713,115 instructions # 0.15 insns per cycle # 22.50 stalled cycles per insn (50.04%) 10,334,910 branches # 1.017 M/sec (50.00%) 1,980,209 branch-misses # 19.16% of all branches (49.96%) 10.163701471 seconds time elapsed |
如果需要统计更多的项，需要使用-e，如：
| perf stat -e task-clock,context-switches,cpu-migrations,page-faults,cycles,stalled-cycles-frontend,stalled-cycles-backend,instructions,branches,branch-misses,L1-dcache-loads,L1-dcache-load-misses,LLC-loads,LLC-load-misses,dTLB-loads,dTLB-load-misses ls |
结果如下，关注的特殊项也纳入统计。
| Performance counter stats for 'ls': 0.976790 task-clock (msec) # 0.618 CPUs utilized 0 context-switches # 0.000 K/sec 0 cpu-migrations # 0.000 K/sec 92 page-faults # 0.094 M/sec 1,801,371 cycles # 1.844 GHz 458,450 stalled-cycles-frontend # 25.45% frontend cycles idle 665,732 stalled-cycles-backend # 36.96% backend cycles idle <not counted> instructions (0.00%) <not counted> branches (0.00%) <not counted> branch-misses (0.00%) <not counted> L1-dcache-loads (0.00%) <not counted> L1-dcache-load-misses (0.00%) <not counted> LLC-loads (0.00%) <not counted> LLC-load-misses (0.00%) <not counted> dTLB-loads (0.00%) <not counted> dTLB-load-misses (0.00%) 0.001580341 seconds time elapsed |
perf record
运行一个命令，并将其数据保存到perf.data中。随后，可以使用perf report进行分析。
perf record和perf report可以更精确的分析一个应用，perf record可以精确到函数级别。并且在函数里面混合显示汇编语言和代码。
创建一个test1.c文件用于测试：
| void longa() { int i,j; for(i = 0; i < 10000000; i++) j=i; //am I silly or crazy? I feel boring and desperate. } void funcA() { int i; for(i=0 ; i < 10; i++) longa(); } void funcB() { int i; for(i = 0; i< 100; i++) longa(); } int main(void) { funcA(); funcB(); } |
编译test1.c文件gcc test1.c -o test1 -g -O0，同时可以使用此方法分析是否选择编译优化产生的结果。-g是只能callgraph功能，-O0是关闭优化。
常用选项
-e record指定PMU事件
--filter event事件过滤器
-a 录取所有CPU的事件
-p 录取指定pid进程的事件
-o 指定录取保存数据的文件名
-g 使能函数调用图功能
-C 录取指定CPU的事件
sudo perf record -g ./test1
会在当前目录生成perf.data文件。
perf record -e cpu-clock ./test1 之路去cpu-clock事件
perf record -e raw_syscalls:sys_enter ./test1录取sys_enter系统调用事件
perf record -g -o perf.test1.data ./test1 保存录取信息到perf.test1.data中
perf report
解析perf record产生的数据，并给出分析结果。
常用参数：
-i 导入的数据文件名称，如果没有则默认为perf.data
-g 生成函数调用关系图
--sort 从更高层面显示分类统计信息，比如： pid, comm, dso, symbol, parent, cpu,socket, srcline, weight, local_weight.
执行sudo perf report -i perf.data，可以看出main函数所占百分比，以及funcA和funcB分别所占百分比。
在funcB执行过程中，还产生了apic timer，占用了一部分cpu资源。除此之外，占比基本上是1：10。
funcA和funcB的占比，基本符合预期。那么进入longa，分析一下热点。
在C和汇编混合显示界面，可以看出for循环占用了69.92%，j=i赋值占用了30.08%。
根据之上描述，可以看出top适合监控整个系统的性能，stat比较适合单个程序的性能分析，record/report更适合对程序进行更细粒度的分析。
perf timechart
perf timechart是将之前的各种统计信息图形化的一个工具。
perf timechart record <option> <command>用于记录整个系统或者一个应用的事件，还可以加option记录指定类型的事件。
perf timechart用于将perf.data转换成SVG格式的文件，SVG可以通过Inkscape或者浏览器打开。
perf timechart record可以指定特定类型的事件：
-P：记录power相关事件
-T：记录任务相关事件
-I：记录io相关事件
-g：记录函数调用关系
perf timechart用于将perf timechart record录取的perf.data转换成output.svg。
-o 指定输出文件名
-i 指定待解析的文件名
-w 输出SVG文件宽度
-P 只显示power相关事件图标
-T , --tasks-only 显示task信息，不显示处理器信息
-p 显示指定进程名称或者PID显示
--symfs=<directory> 指定系统符号表路径
-t, --topology 根据拓扑结构对CPU进行分类
--highlight=<duration_nsecs|task_name> 对运行超过特定时间的task高亮
sudo perf timechart record -T && sudo perf timechart -w 1900结果如下，可以看到相关task的名称，开始时间/结束时间，每个时间点的状态（Running/Idle/Deeper Idle/Deepest Idle/Sleeping/Waiting for Cpu /Blocked on IO）。
记录IO事件：sudo perf timechart record -I && sudo perf timechart -w 1800。
可以看到按应用分类的，Disk/Network/Sync/Poll/Error信息。以及每个应用数据吞吐量。
记录Power状态事件：sudo perf timechart record -I && sudo perf timechart -w 1800。可以看到不同之处在于Idle之类的状态里面还有细分C/C2更详细的显示Power状态。
抓取task-only信息 sudo perf timechart record -I && sudo perf timechart -w 1800，如下。显示了Idle详细信息，Running进程的名称。
perf script
用于读取perf record保存的裸trace数据。
使用方法：
perf script [<options>]
perf script [<options>] record <script> [<record-options>] <command>
perf script [<options>] report <script> [script-args]
perf script [<options>] <script> <required-script-args> [<record-options>] <command>
perf script [<options>] <top-script> [script-args]
perf lock
Need to enable CONFIG_LOCKDEP and CONFIG_LOCK_STAT XXXXXXXXXXXXXXXXXXXXXXXXXX
分析内核锁统计信息。
锁是内核用于同步的方法，一旦加了锁，其他加锁的内核执行路径就必须等待，降低了并行。同时，如果加锁不正确还会造成死锁。
因此对于内核锁进行分析是一项重要的调优工作。
要使用此功能，内核需要编译选项的支持：CONFIG_LOCKDEP、CONFIG_LOCK_STAT。
CONFIG_LOCKDEP defines acquired and release events.
CONFIG_LOCK_STAT defines contended and acquired lock events.
perf lock record：抓取执行命令的lock事件信息到perf.data中
perf lock report：产生统计报告
perf lock script：显示原始lock事件
perf lock info：
-k <value>：sorting key，默认为acquired，还可以按contended、wait_total、wait_max和wait_min来排序。
Name：内核锁的名字。
aquired：该锁被直接获得的次数，因为没有其它内核路径占用该锁，此时不用等待。
contended：该锁等待后获得的次数，此时被其它内核路径占用，需要等待。
total wait：为了获得该锁，总共的等待时间。
max wait：为了获得该锁，最大的等待时间。
min wait：为了获得该锁，最小的等待时间。
perf kmem
perf kmem用于跟踪测量内核slab分配器事件信息。
比如内存分配/释放等。可以用来研究程序在哪里分配了大量内存，或者在什么地方产生碎片之类的和内存管理相关的问题。
perf kmem和perf lock实际上都是perf tracepoint的子类，等同于perf record -e kmem:*和perf record -e lock:*。
但是这些工具在内部队员是数据进行了慧聪和分析，因此统计报表更具可读性。
perf kmem record：抓取命令的内核slab分配器事件
perf kmem stat：生成内核slab分配器统计信息
选项：
--caller 显示每个调用点统计信息
--alloc 显示每次内存分配事件
-s <key[,key2...]>, --sort=<key[,key2...]>
Sort the output (default: frag,hit,bytes for slab and bytes,hit for page). Available sort keys are ptr, callsite, bytes, hit, pingpong, frag for slab and page, callsite, bytes, hit, order, migtype, gfp for page.
This option should be preceded by one of the mode selection options - i.e. --slab, --page, --alloc and/or --caller.
-l <num>, 只显示固定行数
--raw-ip
Print raw ip instead of symbol
--slab 分析slab分配器事件
--page 分析页分配事件
--live
Show live page stat. The perf kmem shows total allocation stat by default, but this option shows live (currently allocated) pages instead. (This option works with --page option only)
| sudo perf kmem record ls |
sudo perf kmem stat只显示概要统计信息：
| SUMMARY (SLAB allocator) ======================== Total bytes requested: 368,589 Total bytes allocated: 369,424 Total bytes wasted on internal fragmentation: 835 Internal fragmentation: 0.226028% Cross CPU allocations: 0/2,256 |
sudo perf kmem --alloc --caller --slab stat显示了更加详细的分类信息：
|
--------------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------- |
该报告有三个部分：根据 Callsite 显示的部分，所谓 Callsite 即内核代码中调用 kmalloc 和 kfree 的地方。
比如上图中的函数proc_reg_open，Hit 栏为 1，表示该函数在 record 期间一共调用了 kmalloc 一次。
对于第一行 Total_alloc/Per 显示为 1024/1024，第一个值 1024 表示函数 proc_reg_open 总共分配的内存大小，Per 表示平均值。
比较有趣的两个参数是 Ping-pong 和 Frag。Frag 比较容易理解，即内部碎片。虽然相对于 Buddy System，Slab 正是要解决内部碎片问题，但 slab 依然存在内部碎片，比如一个 cache 的大小为 1024，但需要分配的数据结构大小为 1022，那么有 2 个字节成为碎片。Frag 即碎片的比例。
Ping-pong 是一种现象，在多 CPU 系统中，多个 CPU 共享的内存会出现”乒乓现象”。一个 CPU 分配内存，其他 CPU 可能访问该内存对象，也可能最终由另外一个 CPU 释放该内存对象。而在多 CPU 系统中，L1 cache 是 per CPU 的，CPU2 修改了内存，那么其他的 CPU 的 cache 都必须更新，这对于性能是一个损失。Perf kmem 在 kfree 事件中判断 CPU 号，如果和 kmalloc 时的不同，则视为一次 ping-pong，理想的情况下 ping-pong 越小越好。Ibm developerworks 上有一篇讲述 oprofile 的文章，其中关于 cache 的调优可以作为很好的参考资料。
Callsite：内核代码中调用kmalloc和kfree的地方。
Total_alloc/Per：总共分配的内存大小，平均每次分配的内存大小。
Total_req/Per：总共请求的内存大小，平均每次请求的内存大小。
Hit：调用的次数。
Ping-pong：kmalloc和kfree不被同一个CPU执行时的次数，这会导致cache效率降低。
Frag：碎片所占的百分比，碎片 = 分配的内存 - 请求的内存，这部分是浪费的。
有使用--alloc选项，还会看到Alloc Ptr，即所分配内存的地址。
后面则有根据被调用地点的显示方式的部分。
最后一个部分是汇总数据，显示总的分配的内存和碎片情况，Cross CPU allocation 即 ping-pong 的汇总。
要分析--page事件，需要在record的时候加上--page选项。sudo perf kmem record --page ls，使用sudo perf kmem stat --page查看结果：
| 0xee318 [0x8]: failed to process type: 68 error during process events: -22 |
perf sched
perf sched专门用于跟踪/测量调度器，包括延时等。
perf sched record <command>：录制测试过程中的调度事件
perf sched latency：报告线程调度延时和其他调度相关属性
perf sched script：查看执行过程中详细的trace信息
perf sched replay：回放perf sched record录制的执行过程
perf sched map:用字符表示打印上下文切换
执行sudo perf sched record ls后，通过不同方式查看结果。
sudo perf sched latency，可以看到ls进程的Average delay/Maximum delay时间。各个 column 的含义如下： Task: 进程的名字和 pid Runtime: 实际运行时间 Switches: 进程切换的次数 Average delay: 平均的调度延迟 Maximum delay: 最大延迟
这里最值得人们关注的是 Maximum delay，一般从这里可以看到对交互性影响最大的特性：调度延迟，如果调度延迟比较大，那么用户就会感受到视频或者音频断断续续的。
|
----------------------------------------------------------------------------------------------------------------- |
sudo perf sched script能看到更详细的sched信息，包括sched_wakeup/sched_switch等等。每一列的含义依次是：进程名/pid/CPU ID/时间戳。
| perf 7801 [002] 5398.722314: sched:sched_stat_sleep: comm=perf pid=7806 delay=110095391 [ns] perf 7801 [002] 5398.722316: sched:sched_wakeup: comm=perf pid=7806 prio=120 target_cpu=004 swapper 0 [004] 5398.722328: sched:sched_stat_wait: comm=perf pid=7806 delay=0 [ns] swapper 0 [004] 5398.722333: sched:sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7806 next_prio=120 perf 7801 [002] 5398.722363: sched:sched_stat_runtime: comm=perf pid=7801 runtime=1255788 [ns] vruntime=3027478102 [ns] perf 7801 [002] 5398.722364: sched:sched_switch: prev_comm=perf prev_pid=7801 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120 perf 7806 [004] 5398.722568: sched:sched_wakeup: comm=migration/4 pid=27 prio=0 target_cpu=004 perf 7806 [004] 5398.722571: sched:sched_stat_runtime: comm=perf pid=7806 runtime=254732 [ns] vruntime=1979611107 [ns] perf 7806 [004] 5398.722575: sched:sched_switch: prev_comm=perf prev_pid=7806 prev_prio=120 prev_state=R+ ==> next_comm=migration/4 next_pid=27 next_prio=0 migration/4 27 [004] 5398.722582: sched:sched_stat_wait: comm=perf pid=7806 delay=13914 [ns] migration/4 27 [004] 5398.722586: sched:sched_migrate_task: comm=perf pid=7806 prio=120 orig_cpu=4 dest_cpu=2 swapper 0 [002] 5398.722595: sched:sched_stat_wait: comm=perf pid=7806 delay=0 [ns] swapper 0 [002] 5398.722596: sched:sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7806 next_prio=120 migration/4 27 [004] 5398.722611: sched:sched_switch: prev_comm=migration/4 prev_pid=27 prev_prio=0 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 ls 7806 [002] 5398.723421: sched:sched_stat_sleep: comm=kworker/u12:3 pid=7064 delay=1226675 [ns] ls 7806 [002] 5398.723423: sched:sched_wakeup: comm=kworker/u12:3 pid=7064 prio=120 target_cpu=003 swapper 0 [003] 5398.723432: sched:sched_stat_wait: comm=kworker/u12:3 pid=7064 delay=0 [ns] swapper 0 [003] 5398.723434: sched:sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u12:3 next_pid=7064 next_prio=120 kworker/u12:3 7064 [003] 5398.723441: sched:sched_stat_sleep: comm=/usr/bin/termin pid=2511 delay=80833386 [ns] kworker/u12:3 7064 [003] 5398.723447: sched:sched_wakeup: comm=/usr/bin/termin pid=2511 prio=120 target_cpu=004 kworker/u12:3 7064 [003] 5398.723449: sched:sched_stat_runtime: comm=kworker/u12:3 pid=7064 runtime=29315 [ns] vruntime=846439549943 [ns] kworker/u12:3 7064 [003] 5398.723451: sched:sched_switch: prev_comm=kworker/u12:3 prev_pid=7064 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 swapper 0 [004] 5398.723462: sched:sched_stat_wait: comm=/usr/bin/termin pid=2511 delay=0 [ns] swapper 0 [004] 5398.723466: sched:sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=/usr/bin/termin next_pid=2511 next_prio=120 ls 7806 [002] 5398.723503: sched:sched_migrate_task: comm=perf pid=7801 prio=120 orig_cpu=2 dest_cpu=3 ls 7806 [002] 5398.723505: sched:sched_stat_sleep: comm=perf pid=7801 delay=1142537 [ns] ls 7806 [002] 5398.723506: sched:sched_wakeup: comm=perf pid=7801 prio=120 target_cpu=003 ls 7806 [002] 5398.723508: sched:sched_stat_runtime: comm=ls pid=7806 runtime=920005 [ns] vruntime=3028398107 [ns] swapper 0 [003] 5398.723508: sched:sched_stat_wait: comm=perf pid=7801 delay=0 [ns] swapper 0 [003] 5398.723508: sched:sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=perf next_pid=7801 next_prio=120 ls 7806 [002] 5398.723510: sched:sched_switch: prev_comm=ls prev_pid=7806 prev_prio=120 prev_state=x ==> next_comm=swapper/2 next_pid=0 next_prio=120 /usr/bin/termin 2511 [004] 5398.723605: sched:sched_stat_runtime: comm=/usr/bin/termin pid=2511 runtime=162720 [ns] vruntime=191386139371 [ns] /usr/bin/termin 2511 [004] 5398.723611: sched:sched_switch: prev_comm=/usr/bin/termin prev_pid=2511 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120 |
sudo perf sched map的好处在于提供了一个的总的视图，将成百上千的调度事件进行总结，显示了系统任务在 CPU 之间的分布，假如有不好的调度迁移，比如一个任务没有被及时迁移到 idle 的 CPU 却被迁移到其他忙碌的 CPU，类似这种调度器的问题可以从 map 的报告中一眼看出来。
星号表示调度事件发生所在的 CPU。
点号表示该 CPU 正在 IDLE。
| *A0 5398.722333 secs A0 => perf:7806 *. A0 5398.722365 secs . => swapper:0 . *B0 5398.722575 secs B0 => migration/4:27 *A0 B0 5398.722597 secs A0 *. 5398.722611 secs A0 *C0 . 5398.723434 secs C0 => kworker/u12:3:7064 A0 *. . 5398.723451 secs A0 . *D0 5398.723467 secs D0 => /usr/bin/termin:2511 A0 *E0 D0 5398.723509 secs E0 => perf:7801 *. E0 D0 5398.723510 secs . E0 *. 5398.723612 secs |
perf sched replay 这个工具更是专门为调度器开发人员所设计，它试图重放 perf.data 文件中所记录的调度场景。很多情况下，一般用户假如发现调度器的奇怪行为，他们也无法准确说明发生该情形的场景，或者一些测试场景不容易再次重现，或者仅仅是出于“偷懒”的目的，使用 perf replay，perf 将模拟 perf.data 中的场景，无需开发人员花费很多的时间去重现过去，这尤其利于调试过程，因为需要一而再，再而三地重复新的修改是否能改善原始的调度场景所发现的问题。
| run measurement overhead: 166 nsecs sleep measurement overhead: 52177 nsecs the run test took 999975 nsecs the sleep test took 1064623 nsecs nr_run_events: 11 nr_sleep_events: 581 nr_wakeup_events: 5 task 0 ( swapper: 0), nr_events: 11 task 1 ( swapper: 1), nr_events: 1 task 2 ( swapper: 2), nr_events: 1 task 3 ( kthreadd: 3), nr_events: 1 ... task 563 ( kthreadd: 7509), nr_events: 1 task 564 ( bash: 7751), nr_events: 1 task 565 ( man: 7762), nr_events: 1 task 566 ( kthreadd: 7789), nr_events: 1 task 567 ( bash: 7800), nr_events: 1 task 568 ( sudo: 7801), nr_events: 4 task 569 ( perf: 7806), nr_events: 8 ------------------------------------------------------------ #1 : 25.887, ravg: 25.89, cpu: 1919.68 / 1919.68 #2 : 27.994, ravg: 26.10, cpu: 2887.76 / 2016.49 #3 : 26.403, ravg: 26.13, cpu: 2976.09 / 2112.45 #4 : 29.400, ravg: 26.46, cpu: 1015.01 / 2002.70 #5 : 26.750, ravg: 26.49, cpu: 2942.80 / 2096.71 #6 : 27.647, ravg: 26.60, cpu: 3087.37 / 2195.78 #7 : 31.405, ravg: 27.08, cpu: 2762.43 / 2252.44 #8 : 23.770, ravg: 26.75, cpu: 2172.55 / 2244.45 #9 : 26.952, ravg: 26.77, cpu: 2794.93 / 2299.50 #10 : 30.904, ravg: 27.18, cpu: 973.26 / 2166.88 |
perf probe
Need to find vmlinux XXXXXXXXXXXXXXXXXX
可以自定义探测点。
Define new dynamic tracepoints.
使用例子
(1) Display which lines in schedule() can be probed
# perf probe --line schedule
前面有行号的可以探测，没有行号的就不行了。
(2) Add a probe on schedule() function 12th line.
# perf probe -a schedule:12
在schedule函数的12处增加一个探测点。
perf bench
perf bench作为benchmark工具的通用框架，包含sched/mem/numa/futex等子系统，all可以指定所有。
perf bench sched：调度器和IPC机制。包含messaging和pipe两个功能。
perf bench mem：内存存取性能。包含memcpy和memset两个功能。
perf bench numa：NUMA架构的调度和内存处理性能。包含mem功能。
perf bench futex：futex压力测试。包含hash/wake/wake-parallel/requeue/lock-pi功能。
perf bench all：所有bench测试的集合
perf bench sched all，显示了messaging和pipi两部分性能。
sched message 是从经典的测试程序 hackbench 移植而来，用来衡量调度器的性能，overhead 以及可扩展性。该 benchmark 启动 N 个 reader/sender 进程或线程对，通过 IPC(socket 或者 pipe) 进行并发的读写。一般人们将 N 不断加大来衡量调度器的可扩展性。Sched message 的用法及用途和 hackbench 一样。
secsched pipe 从 Ingo Molnar 的 pipe-test-1m.c 移植而来。当初 Ingo 的原始程序是为了测试不同的调度器的性能和公平性的。其工作原理很简单，两个进程互相通过 pipe 拼命地发 1000000 个整数，进程 A 发给 B，同时 B 发给 A。。。因为 A 和 B 互相依赖，因此假如调度器不公平，对 A 比 B 好，那么 A 和 B 整体所需要的时间就会更长。
| # 20 sender and receiver processes per group # 10 groups == 400 processes run Total time: 0.158 [sec] # Running sched/pipe benchmark... # Executed 1000000 pipe operations between two processes Total time: 10.089 [sec] 10.089625 usecs/op 99111 ops/sec |
perf bench mem all
该测试衡量 不同版本的memcpy/memset/ 函数处理一个 1M 数据的所花费的时间，转换成吞吐率。
| # Running mem/memcpy benchmark... # function 'default' (Default memcpy() provided by glibc) # Copying 1MB bytes ... 1.242446 GB/sec # function 'x86-64-unrolled' (unrolled memcpy() in arch/x86/lib/memcpy_64.S) # Copying 1MB bytes ... 3.160396 GB/sec # function 'x86-64-movsq' (movsq-based memcpy() in arch/x86/lib/memcpy_64.S) # Copying 1MB bytes ... 3.090388 GB/sec # function 'x86-64-movsb' (movsb-based memcpy() in arch/x86/lib/memcpy_64.S) # Copying 1MB bytes ... 3.180985 GB/sec # Running mem/memset benchmark... # function 'default' (Default memset() provided by glibc) # Copying 1MB bytes ... 8.642146 GB/sec # function 'x86-64-unrolled' (unrolled memset() in arch/x86/lib/memset_64.S) # Copying 1MB bytes ... 8.642146 GB/sec # function 'x86-64-stosq' (movsq-based memset() in arch/x86/lib/memset_64.S) # Copying 1MB bytes ... 8.719308 GB/sec # function 'x86-64-stosb' (movsb-based memset() in arch/x86/lib/memset_64.S) # Copying 1MB bytes ... 8.642146 GB/sec |
perf bench futex，Futex是一种用户态和内核态混合机制，所以需要两个部分合作完成，linux上提供了sys_futex系统调用，对进程竞争情况下的同步处理提供支持。
所有的futex同步操作都应该从用户空间开始，首先创建一个futex同步变量，也就是位于共享内存的一个整型计数器。
当 进程尝试持有锁或者要进入互斥区的时候，对futex执行"down"操作，即原子性的给futex同步变量减1。如果同步变量变为0，则没有竞争发生， 进程照常执行。如果同步变量是个负数，则意味着有竞争发生，需要调用futex系统调用的futex_wait操作休眠当前进程。
当进程释放锁或 者要离开互斥区的时候，对futex进行"up"操作，即原子性的给futex同步变量加1。如果同步变量由0变成1，则没有竞争发生，进程照常执行。如 果加之前同步变量是负数，则意味着有竞争发生，需要调用futex系统调用的futex_wake操作唤醒一个或者多个等待进程。
| # Running futex/hash benchmark... Run summary [PID 29778]: 5 threads, each operating on 1024 [private] futexes for 10 secs. [thread 0] futexes: 0x3421d20 ... 0x3422d1c [ 4050227 ops/sec ] [thread 1] futexes: 0x3422d30 ... 0x3423d2c [ 4015308 ops/sec ] [thread 2] futexes: 0x3423eb0 ... 0x3424eac [ 3824537 ops/sec ] [thread 3] futexes: 0x3425030 ... 0x342602c [ 4016025 ops/sec ] [thread 4] futexes: 0x34261b0 ... 0x34271ac [ 4180992 ops/sec ] Averaged 4017417 operations/sec (+- 1.42%), total secs = 10 # Running futex/wake benchmark... Run summary [PID 29778]: blocking on 5 threads (at [private] futex 0x7ef6ac), waking up 1 at a time. [Run 1]: Wokeup 5 of 5 threads in 0.0310 ms [Run 2]: Wokeup 5 of 5 threads in 0.0350 ms [Run 3]: Wokeup 5 of 5 threads in 0.0310 ms [Run 4]: Wokeup 5 of 5 threads in 0.0320 ms [Run 5]: Wokeup 5 of 5 threads in 0.0310 ms [Run 6]: Wokeup 5 of 5 threads in 0.0300 ms [Run 7]: Wokeup 5 of 5 threads in 0.0320 ms [Run 8]: Wokeup 5 of 5 threads in 0.0300 ms [Run 9]: Wokeup 5 of 5 threads in 0.0230 ms [Run 10]: Wokeup 5 of 5 threads in 0.0310 ms Wokeup 5 of 5 threads in 0.0306 ms (+-3.13%) # Running futex/wake-parallel benchmark... Run summary [PID 29778]: blocking on 5 threads (at [private] futex 0x7ef820), 5 threads waking up 1 at a time. [Run 1]: Avg per-thread latency (waking 1/5 threads) in 0.0208 ms (+-71.27%) [Run 2]: Avg per-thread latency (waking 1/5 threads) in 0.0166 ms (+-56.05%) [Run 3]: Avg per-thread latency (waking 1/5 threads) in 0.0286 ms (+-45.52%) [Run 4]: Avg per-thread latency (waking 1/5 threads) in 0.0168 ms (+-33.11%) [Run 5]: Avg per-thread latency (waking 1/5 threads) in 0.0146 ms (+-45.26%) [Run 6]: Avg per-thread latency (waking 1/5 threads) in 0.0158 ms (+-55.59%) [Run 7]: Avg per-thread latency (waking 1/5 threads) in 0.0316 ms (+-74.73%) [Run 8]: Avg per-thread latency (waking 1/5 threads) in 0.0346 ms (+-47.43%) [Run 9]: Avg per-thread latency (waking 1/5 threads) in 0.0230 ms (+-73.03%) [Run 10]: Avg per-thread latency (waking 1/5 threads) in 0.0270 ms (+-43.30%) Avg per-thread latency (waking 1/5 threads) in 0.0229 ms (+-17.57%) # Running futex/requeue benchmark... Run summary [PID 29778]: Requeuing 5 threads (from [private] 0x7ef99c to 0x7ef998), 1 at a time. [Run 1]: Requeued 5 of 5 threads in 0.0090 ms [Run 2]: Requeued 5 of 5 threads in 0.0090 ms [Run 3]: Requeued 5 of 5 threads in 0.0080 ms [Run 4]: Requeued 5 of 5 threads in 0.0090 ms [Run 5]: Requeued 5 of 5 threads in 0.0090 ms [Run 6]: Requeued 5 of 5 threads in 0.0090 ms [Run 7]: Requeued 5 of 5 threads in 0.0100 ms [Run 8]: Requeued 5 of 5 threads in 0.0080 ms [Run 9]: Requeued 5 of 5 threads in 0.0090 ms [Run 10]: Requeued 5 of 5 threads in 0.0090 ms Requeued 5 of 5 threads in 0.0089 ms (+-2.02%) # Running futex/lock-pi benchmark... Run summary [PID 29778]: 5 threads doing pi lock/unlock pairing for 10 secs. [thread 0] futex: 0x7efaa0 [ 2550 ops/sec ] [thread 1] futex: 0x7efaa0 [ 2550 ops/sec ] [thread 2] futex: 0x7efaa0 [ 2549 ops/sec ] [thread 3] futex: 0x7efaa0 [ 2550 ops/sec ] [thread 4] futex: 0x7efaa0 [ 2550 ops/sec ] Averaged 2549 operations/sec (+- 0.01%), total secs = 10 |
perf trace
通常，面对看似复杂，实则较有规律的计算机输出，程序员们总是会用脚本来进行处理：比如给定一个文本文件，想从中找出有多少个数字 0125，人们不会打开文件然后用肉眼去一个一个地数，而是用 grep 命令来进行处理。
perf 的输出虽然是文本格式，但还是不太容易分析和阅读。往往也需要进一步处理，perl 和 python 是目前最强大的两种脚本语言。Tom Zanussi 将 perl 和 python 解析器嵌入到 perf 程序中，从而使得 perf 能够自动执行 perl 或者 python 脚本进一步进行处理，从而为 perf 提供了强大的扩展能力。因为任何人都可以编写新的脚本，对 perf 的原始输出数据进行所需要的进一步处理。这个特性所带来的好处很类似于 plug-in 之于 eclipse。
下面的命令可以查看系统中已经安装的脚本：
# perf trace -l
List of available trace scripts:
syscall-counts [comm] system-wide syscall counts
syscall-counts-by-pid [comm] system-wide syscall counts, by pid
failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid
。。。
比如 failed-syscalls 脚本，执行的效果如下：
# perf trace record failed-syscalls
^C[ perf record: Woken up 11 times to write data ]
[ perf record: Captured and wrote 1.939 MB perf.data (~84709 samples) ]
perf trace report failed-syscalls
perf trace started with Perl script \
/root/libexec/perf-core/scripts/perl/failed-syscalls.pl
failed syscalls, by comm:
comm # errors
-------------------- ----------
firefox 1721
claws-mail 149
konsole 99
X 77
emacs 56
[...]
failed syscalls, by syscall:
syscall # errors
------------------------------ ----------
sys_read 2042
sys_futex 130
sys_mmap_pgoff 71
sys_access 33
sys_stat64 5
sys_inotify_add_watch 4
[...]
该报表分别按进程和按系统调用显示失败的次数。非常简单明了，而如果通过普通的 perf record 加 perf report 命令，则需要自己手工或者编写脚本来统计这些数字。
参考资料
系统级性能分析工具 — Perf：http://blog.csdn.net/zhangskd/article/details/37902159/
linux perf - 性能测试和优化工具：http://www.cnblogs.com/hushaojun/p/4848269.html
Linux下的内核测试工具——perf使用简介：http://www.blogjava.net/qileilove/archive/2013/09/04/403646.html
Perf -- Linux下的系统性能调优工具，第 1 部分：http://www.ibm.com/developerworks/cn/linux/l-cn-perf1/
Perf -- Linux下的系统性能调优工具，第 2 部分：https://www.ibm.com/developerworks/cn/linux/l-cn-perf2/
性能分析工具---Perf简介汇总整理：http://sanwen.net/a/nzsrvoo.html
本文来自博客园，作者：sunsky303，转载请注明原文链接：https://www.cnblogs.com/sunsky303/p/8328836.html
