;
编译fork.c文件gcc fork.c -o fork-g -O0,同时可以使用此方法分析是否选择编译优化产生的结果。-g是只能callgraph功能,-O0是关闭优化。
-e record指定PMU事件
--filter event事件过滤器
-a 录取所有CPU的事件
-p 录取指定pid进程的事件
-o 指定录取保存数据的文件名
-g 使能函数调用图功能
-C 录取指定CPU的事件
sudo perf record -a -g ./fork:会在当前目录生成perf.data文件。
sudo perf report --call-graph none结果如下,后面结合perf timechart分析.
上图看上去比较乱,如果想只看fork产生的信息:
sudo perf report --call-graph none -c fork
-i 导入的数据文件名称,如果没有则默认为perf.data
-g 生成函数调用关系图,此时内核要打开CONFIG_KALLSYMS;用户空间库或者执行文件需要带符号信息(not stripped),编译选项需要加上-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 report -g的时候,可能会提示Failed to open /lib/libpthread-0.9.33.2.so, continuing without symbols。
这时候通过file xxx查看,如果提示xxxx stripped表示此文件不包含符号信息,需要xxxx not stripped文件。
3.6 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。
-w调整输出的svg文件长度,可以查看更多细节。
-p可以指定只查看某些进程输出,使用方式:sudo perf timechart -p test1 -p thermald
-o 指定输出文件名
-i 指定待解析的文件名
-w 输出SVG文件宽度
-P 只显示power相关事件图标
-T , --tasks-only 显示task信息,不显示处理器信息
-p 显示指定进程名称或者PID显示
--symfs=<directory> 指定系统符号表路径
-t, --topology 根据拓扑结构对CPU进行分类
--highlight=<duration_nsecs|task_name> 对运行超过特定时间的task高亮
结果如下,可以看到相关task的名称,开始时间/结束时间,每个时间点的状态(Running/Idle/Deeper Idle/Deepest Idle/Sleeping/Waiting for Cpu /Blocked on IO)。
3.6.1 结合perf timechart和perf report分析函数占比
由perf report可知test_little、test_medium、test_high、test_hi四个函数占比分别为3.84%、12.01%、22.99%、30.43%。
有代码可知如果以test_little为1单位,那么test_medium就为2单位,test_high为3单位,test_hi为4单位。
四个函数执行次数分别为2、4、4、4,所以四个函数每个单位对应CPU占比为:
test_little - 3.84%/2=1.9%
test_medium - 12.01%/4/2=1.5%
test_high - 22.99/4/3=1.9%
test_hi - 30.43%/4/4=1.9%
基本上符合预期。
记录IO事件,可以看到按应用分类的,Disk/Network/Sync/Poll/Error信息。以及每个应用数据吞吐量。
sudo perf timechart record -I && sudo perf timechart -w 1800。
用于读取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]
还可以编写perl或者python脚本进行数据分析。
3.8 perf lock
3.8.1 perf lock内核配置
要使用此功能,内核需要编译选项的支持:CONFIG_LOCKDEP、CONFIG_LOCK_STAT。
CONFIG_LOCKDEP defines acquired and release events.
CONFIG_LOCK_STAT defines contended and acquired lock events.
CONFIG_LOCKDEP=y
CONFIG_LOCK_STAT=y
分析内核锁统计信息。
锁是内核用于同步的方法,一旦加了锁,其他加锁的内核执行路径就必须等待,降低了并行。同时,如果加锁不正确还会造成死锁。
因此对于内核锁进行分析是一项重要的调优工作。
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:为了获得该锁,最小的等待时间。
3.9 perf kmem
3.9.1 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)
---------------------------------------------------------------------------------------------------------
Callsite | Total_alloc/Per | Total_req/Per | Hit | Ping-pong | Frag
---------------------------------------------------------------------------------------------------------
proc_reg_open+32 | 64/64 | 40/40 | 1 | 0 | 37.500%
seq_open+34 | 384/192 | 272/136 | 2 | 0 | 29.167%
apparmor_file_alloc_security+5c | 608/32 | 456/24 | 19 | 1 | 25.000%
ext4_readdir+8bd | 64/64 | 48/48 | 1 | 0 | 25.000%
ext4_htree_store_dirent+3e | 896/68 | 770/59 | 13 | 0 | 14.062%
load_elf_phdrs+64 | 1024/512 | 896/448 | 2 | 0 | 12.500%
load_elf_binary+222 | 32/32 | 28/28 | 1 | 0 | 12.500%
anon_vma_prepare+11b | 1280/80 | 1152/72 | 16 | 0 | 10.000%
inotify_handle_event+75 | 73664/64 | 66758/58 | 1151 | 0 | 9.375%
do_execveat_common.isra.33+e5 | 2048/256 | 1920/240 | 8 | 1 | 6.250%
... | ... | ... | ... | ... | ...
---------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------
Alloc Ptr | Total_alloc/Per | Total_req/Per | Hit | Ping-pong | Frag
---------------------------------------------------------------------------------------------------------
0xffff8800ca4d86c0 | 192/192 | 136/136 | 1 | 0 | 29.167%
0xffff8801ea05aa80 | 192/192 | 136/136 | 1 | 0 | 29.167%
0xffff8801f6ad6540 | 96/96 | 68/68 | 1 | 0 | 29.167%
0xffff8801f6ad6f00 | 96/96 | 68/68 | 1 | 0 | 29.167%
0xffff880214e65e80 | 96/32 | 72/24 | 3 | 0 | 25.000%
0xffff8801f45ddac0 | 64/64 | 48/48 | 1 | 0 | 25.000%
0xffff8800ac4093c0 | 32/32 | 24/24 | 1 | 1 | 25.000%
0xffff8800af5a4260 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e651e0 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e65220 | 32/32 | 24/24 | 1 | 0 | 25.000%
0xffff880214e654e0 | 32/32 | 24/24 | 1 | 0 | 25.000%
---------------------------------------------------------------------------------------------------------
SUMMARY (SLAB allocator)
========================
Total bytes requested: 409,260
Total bytes allocated: 417,008
Total bytes wasted on internal fragmentation: 7,748
Internal fragmentation: 1.857998%
Cross CPU allocations: 0/2,833
该报告有三个部分:根据 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 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,一般从这里可以看到对交互性影响最大的特性:调度延迟,如果调度延迟比较大,那么用户就会感受到视频或者音频断断续续的。
-----------------------------------------------------------------------------------------------------------------
Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |
-----------------------------------------------------------------------------------------------------------------
/usr/bin/termin:2511 | 0.163 ms | 1 | avg: 0.019 ms | max: 0.019 ms | max at: 5398.723467 s
ls:7806 | 1.175 ms | 1 | avg: 0.017 ms | max: 0.017 ms | max at: 5398.722333 s
kworker/u12:3:7064 | 0.029 ms | 1 | avg: 0.011 ms | max: 0.011 ms | max at: 5398.723434 s
migration/4:27 | 0.000 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 5398.722575 s
perf:7801 | 1.256 ms | 1 | avg: 0.002 ms | max: 0.002 ms | max at: 5398.723509 s
-----------------------------------------------------------------------------------------------------------------
TOTAL: | 2.623 ms | 5 |
---------------------------------------------------
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
(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处增加一个探测点。
3.14 perf trace
perf trace类似于strace,但增加了其他系统事件的分析,比如pagefaults、task lifetime事件、scheduling事件等。
下面的命令可以查看系统中已经安装的脚本: