Perf -- Linux下的系统性能调优工具介绍

来源:互联网 发布:2016cf东东数据刷枪 编辑:程序博客网 时间:2024/04/30 10:52

Perf简介

Perf是Linux kernel自带的系统性能优化工具。虽然它的版本还只是0.0.2,Perf已经显现出它强大的实力,足以与目前Linux流行的OProfile相媲美了。

Perf的优势在于与Linux Kernel的紧密结合,它可以最先应用到加入Kernel的new feature。而像OProfile, GProf等通常会“慢一拍”。Perf的基本原理跟OProfile等类似,也是在CPU的PMU registers中Get/Set performance counters来获得诸如instructions executed, cache-missed suffered, branches mispredicted等信息。Linux kernel对这些registers进行了一系列抽象,所以你可以按进程,按CPU或者按counter group等不同类别来查看Sample信息。

 

使用Perf

Perf的使用流程和OProfile很像。所以如果你会用OProfile的话,用Perf就很简单。这里只是简单翻译一下在[1]中的Perf examples中举的例子。有更多发现的话以后会继续更新。

$ perf record -f -- git gc   Counting objects: 1283571, done.Compressing objects: 100% (206724/206724), done.Writing objects: 100% (1283571/1283571), done.Total 1283571 (delta 1070675), reused 1281443 (delta 1068566)[ perf record: Captured and wrote 31.054 MB perf.data (~1356768 samples) ]
 
$ perf report --sort comm,dso,symbol | head -10# Samples: 1355726## Overhead          Command                            Shared Object  Symbol# ........  ...............  .......................................  ......#    31.53%              git  /usr/bin/git                             [.] 0x0000000009804f    13.41%        git-prune  /usr/bin/git-prune                       [.] 0x000000000ad06d    10.05%              git  /lib/tls/i686/cmov/libc-2.8.90.so        [.] _nl_make_l10nflist     5.36%        git-prune  /usr/lib/libz.so.1.2.3.3                 [.] 0x00000000009d51     4.48%              git  /lib/tls/i686/cmov/libc-2.8.90.so        [.] memcpy

perf record相当于opcontrol –-start, 而perf report相当于opreport.

Perf用例

查看所有可用的counters用'perf list’:

titan:~> perf list [...] kmem:kmalloc                             [Tracepoint event] kmem:kmem_cache_alloc                    [Tracepoint event] kmem:kmalloc_node                        [Tracepoint event] kmem:kmem_cache_alloc_node               [Tracepoint event] kmem:kfree                               [Tracepoint event] kmem:kmem_cache_free                     [Tracepoint event] kmem:mm_page_free_direct                 [Tracepoint event] kmem:mm_pagevec_free                     [Tracepoint event] kmem:mm_page_alloc                       [Tracepoint event] kmem:mm_page_alloc_zone_locked           [Tracepoint event] kmem:mm_page_pcpu_drain                  [Tracepoint event] kmem:mm_page_alloc_extfrag               [Tracepoint event]
你可以用以上counter的任意组合来跑你的测试程序。比如,用以下命令来看跑
hackbench时page alloc/free的次数。
titan:~> perf stat -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc -e kmem:mm_pagevec_free -e kmem:mm_page_free_direct ./hackbench 10Time: 0.575Performance counter stats for './hackbench 10':         13857  kmem:mm_page_pcpu_drain          27576  kmem:mm_page_alloc                6025  kmem:mm_pagevec_free             20934  kmem:mm_page_free_direct   0.613972165  seconds time elapsed
Perf可以帮你统计N次结果的数值波动情况:
titan:~> perf stat --repeat 5 -e kmem:mm_page_pcpu_drain -e   kmem:mm_page_alloc -e kmem:mm_pagevec_free -e   kmem:mm_page_free_direct ./hackbench 10Time: 0.627Time: 0.644Time: 0.564Time: 0.559Time: 0.626
Performance counter stats for './hackbench 10' (5 runs):         12920  kmem:mm_page_pcpu_drain    ( +-   3.359% )         25035  kmem:mm_page_alloc         ( +-   3.783% )          6104  kmem:mm_pagevec_free       ( +-   0.934% )         18376  kmem:mm_page_free_direct   ( +-   4.941% )   0.643954516  seconds time elapsed   ( +-   2.363% )
有了以上的统计数据,你可以开始sample某一个你关心的tracepoint(比如page
allocations):
titan:~/git> perf record -f -e kmem:mm_page_alloc -c 1 ./git gcCounting objects: 1148, done.Delta compression using up to 2 threads.Compressing objects: 100% (450/450), done.Writing objects: 100% (1148/1148), done.Total 1148 (delta 690), reused 1148 (delta 690)[ perf record: Captured and wrote 0.267 MB perf.data (~11679 samples) ]
查看哪个function引起了page allocations:
titan:~/git> perf report# Samples: 10646## Overhead          Command               Shared Object# ........  ...............  ..........................#   23.57%       git-repack  /lib64/libc-2.5.so           21.81%              git  /lib64/libc-2.5.so           14.59%              git  ./git                        11.79%       git-repack  ./git                         7.12%              git  /lib64/ld-2.5.so              3.16%       git-repack  /lib64/libpthread-2.5.so      2.09%       git-repack  /bin/bash                     1.97%               rm  /lib64/libc-2.5.so            1.39%               mv  /lib64/ld-2.5.so              1.37%               mv  /lib64/libc-2.5.so            1.12%       git-repack  /lib64/ld-2.5.so              0.95%               rm  /lib64/ld-2.5.so              0.90%  git-update-serv  /lib64/libc-2.5.so            0.73%  git-update-serv  /lib64/ld-2.5.so              0.68%             perf  /lib64/libpthread-2.5.so      0.64%       git-repack  /usr/lib64/libz.so.1.2.3  

更进一步的查看:

titan:~/git> perf report --sort comm,dso,symbol

# Samples: 10646## Overhead          Command               Shared Object  Symbol# ........  ...............  ..........................  ......#    9.35%       git-repack  ./git                       [.] insert_obj_hash    9.12%              git  ./git                       [.] insert_obj_hash    7.31%              git  /lib64/libc-2.5.so          [.] memcpy    6.34%       git-repack  /lib64/libc-2.5.so          [.] _int_malloc    6.24%       git-repack  /lib64/libc-2.5.so          [.] memcpy    5.82%       git-repack  /lib64/libc-2.5.so          [.] __GI___fork    5.47%              git  /lib64/libc-2.5.so          [.] _int_malloc    2.99%              git  /lib64/libc-2.5.so          [.] memset
 
同时,call-graph(函数调用图)也可以被记录下来,并且能告诉你每个函数所占用的百分比。
titan:~/git> perf record -f -g -e kmem:mm_page_alloc -c 1 ./git gcCounting objects: 1148, done.Delta compression using up to 2 threads.Compressing objects: 100% (450/450), done.Writing objects: 100% (1148/1148), done.Total 1148 (delta 690), reused 1148 (delta 690)[ perf record: Captured and wrote 0.963 MB perf.data (~42069 samples) ]
titan:~/git> perf report -g# Samples: 10686## Overhead          Command               Shared Object# ........  ...............  ..........................#   23.25%       git-repack  /lib64/libc-2.5.so                       |                         |--50.00%-- _int_free               |                         |--37.50%-- __GI___fork               |          make_child               |                         |--12.50%-- ptmalloc_unlock_all2               |          make_child               |                          --6.25%-- __GI_strcpy   21.61%              git  /lib64/libc-2.5.so                       |                         |--30.00%-- __GI_read               |          |                         |           --83.33%-- git_config_from_file               |                     git_config               |                     |            [...]
用以下命令可以查看整个系统10秒内的page allocation次数:

titan:~/git> perf stat -a -e kmem:mm_page_pcpu_drain -e kmem:mm_page_alloc -e kmem:mm_pagevec_free -e kmem:mm_page_free_direct sleep 10

Performance counter stats for 'sleep 10':
        171585  kmem:mm_page_pcpu_drain         322114  kmem:mm_page_alloc               73623  kmem:mm_pagevec_free            254115  kmem:mm_page_free_direct  10.000591410  seconds time elapsed

用以下命令查看每隔1秒,系统page allocation的波动状况:

titan:~/git> perf stat --repeat 10 -a -e kmem:mm_page_pcpu_drain -e   kmem:mm_page_alloc -e kmem:mm_pagevec_free -e   kmem:mm_page_free_direct sleep 1
Performance counter stats for 'sleep 1' (10 runs):         17254  kmem:mm_page_pcpu_drain    ( +-   3.709% )         34394  kmem:mm_page_alloc         ( +-   4.617% )          7509  kmem:mm_pagevec_free       ( +-   4.820% )         25653  kmem:mm_page_free_direct   ( +-   3.672% )   1.058135029  seconds time elapsed   ( +-   3.089% )

通过反汇编往往能找出是哪行代码生成的指令会引起问题。

titan:~/git> perf annotate __GI___fork------------------------------------------------ Percent |      Source code & Disassembly of libc-2.5.so------------------------------------------------  :  :  :      Disassembly of section .plt:  :      Disassembly of section .text:  :  :      00000031a2e95560 <__fork>:[...]    0.00 :        31a2e95602:   b8 38 00 00 00          mov    $0x38,%eax    0.00 :        31a2e95607:   0f 05                   syscall    83.42 :        31a2e95609:   48 3d 00 f0 ff ff       cmp    $0xfffffffffffff000,%rax    0.00 :        31a2e9560f:   0f 87 4d 01 00 00       ja     31a2e95762 <__fork+0x202>    0.00 :        31a2e95615:   85 c0                   test  %eax,%eax
以上结果显示__GI__forks的83.42%的时间来源于0x38的系统调用。

值得优化某个特定的函数吗?

你也许想知道是否值得去优化你程序中的某个特定函数。一个很好的例子是git mailing list中讨论的关于SHA1 哈希算法优化的问题,我们可以用perf来预判优化的结果。具体参见Linus的回信[2].

"perf report --sort comm,dso,symbol" profiling shows the following for 'git fsck --full' on the kernel repo, using the Mozilla SHA1:   47.69%               git  /home/torvalds/git/git     [.] moz_SHA1_Update   22.98%               git  /lib64/libz.so.1.2.3       [.] inflate_fast    7.32%               git  /lib64/libc-2.10.1.so      [.] __GI_memcpy    4.66%               git  /lib64/libz.so.1.2.3       [.] inflate    3.76%               git  /lib64/libz.so.1.2.3       [.] adler32    2.86%               git  /lib64/libz.so.1.2.3       [.] inflate_table    2.41%               git  /home/torvalds/git/git     [.] lookup_object    1.31%               git  /lib64/libc-2.10.1.so      [.] _int_malloc    0.84%               git  /home/torvalds/git/git     [.] patch_delta    0.78%               git  [kernel]                   [k] hpet_next_event

很明显,SHA1加密算法的性能在这里很关键。

如何测量latency

如果你在build kernel时enabled了

 CONFIG_PERF_COUNTER=y  CONFIG_EVENT_TRACING=y

那你可以加-tip参数来使用几个新的performance counter来测量scheduler的lantencies。

perf stat -e sched:sched_stat_wait -e task-clock ./hackbench 20

以上命令能够得出等待CPU用了多少时间。你可以重复10次这样的操作:

aldebaran:/home/mingo> perf stat --repeat 10 -e /             sched:sched_stat_wait:r -e task-clock ./hackbench 20Time: 0.251Time: 0.214Time: 0.254Time: 0.278Time: 0.245Time: 0.308Time: 0.242Time: 0.222Time: 0.268Time: 0.244
Performance counter stats for './hackbench 20' (10 runs):
         59826  sched:sched_stat_wait    #      0.026 M/sec   ( +-   5.540% )   2280.099643  task-clock-msecs         #      7.525 CPUs    ( +-   1.620% )
   0.303013390  seconds time elapsed   ( +-   3.189% )
读取scheduling的events counter
# perf list 2>&1 | grep sched: sched:sched_kthread_stop                   [Tracepoint event] sched:sched_kthread_stop_ret               [Tracepoint event] sched:sched_wait_task                      [Tracepoint event] sched:sched_wakeup                         [Tracepoint event] sched:sched_wakeup_new                     [Tracepoint event] sched:sched_switch                         [Tracepoint event] sched:sched_migrate_task                   [Tracepoint event] sched:sched_process_free                   [Tracepoint event] sched:sched_process_exit                   [Tracepoint event] sched:sched_process_wait                   [Tracepoint event] sched:sched_process_fork                   [Tracepoint event] sched:sched_signal_send                    [Tracepoint event] sched:sched_stat_wait                      [Tracepoint event] sched:sched_stat_sleep                     [Tracepoint event] sched:sched_stat_iowait                    [Tracepoint event]

对于latency analysis而言,stat_wait/sleep/iowait是值得注意的event。如果你想看所有delays和它们的mix/max/avg,你可以:

 perf record -e sched:sched_stat_wait:r -f -R -c 1 ./hackbench 20 perf trace

 

Reference:

1. https://perf.wiki.kernel.org/index.php/Main_Page

2. http://thread.gmane.org/gmane.comp.version-control.git/124745

原创粉丝点击