perf工具与perf report children的含义

perf 工具简介

perf全名是Performance Event，是在Linux 2.6.31以后内置的系统效能分析工具，Perf的核心功能主要为三块，一是使用perf stat对事件进行统计，二是基于perf record对事件进行采样分析，三是使用perf top进行实时分析。如果仅要了解perf report call-graph形式输出中 children的含义，拉到最后即可。

一、perf事件

通过perf list命令可以查看perf支持的所有事件列表。Perf能够分析的事件主要包括3类，Hardware event硬件事件，Software event软件事件，Tracepoint event追踪点事件。不同的平台中perf能够支持的事件会产生差异。比如我用通用的aarch64工具链编译内核的 4.4.53版本得到的perf，在我这边特定的嵌入式环境下支持的事件列表如下。

# ./perf list 

List of pre-defined events (to be used in -e):

  alignment-faults                                   [Software event]
  bpf-output                                         [Software event]
  context-switches OR cs                             [Software event]
  cpu-clock                                          [Software event]
  cpu-migrations OR migrations                       [Software event]
  dummy                                              [Software event]
  emulation-faults                                   [Software event]
  major-faults                                       [Software event]
  minor-faults                                       [Software event]
  page-faults OR faults                              [Software event]
  task-clock                                         [Software event]

  rNNN                                               [Raw hardware event descriptor]
  cpu/t1=v1[,t2=v2,t3 ...]/modifier                  [Raw hardware event descriptor]
   (see 'man perf-list' on how to encode it)

  mem:[/len][:access]                          [Hardware breakpoint]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

在采样中，如果支持cycles事件，则在不指定采样事件时，默认会采样cycles，如果不支持，则会采集cpu-clock。至少在我实验的环境下如此。

二、perf stat

对任何支持的事件，perf都支持对进程的执行过程进行完整的统计，发生的事件结果会进行简单的聚合，然后在进程运行结束时呈现在标准输出中。比如如下的命令即统计了通过dd生成一个包含1000000个block的文件的消耗时间情况，cpu时钟数，进程切换次数，缺页次数等等信息。

perf stat -B dd if=/dev/zero of=/root/file_tmp count=1000000
1000000+0 records in
1000000+0 records out
512000000 bytes (512 MB) copied, 3.66158 s, 140 MB/s

 Performance counter stats for 'dd if=/dev/zero of=/root/file_tmp count=1000000':

       3618.685991      task-clock (msec)         #    0.988 CPUs utilized
                25      context-switches          #    0.007 K/sec
                 2      cpu-migrations            #    0.001 K/sec
                69      page-faults               #    0.019 K/sec
     8,064,329,026      cycles                    #    2.229 GHz
     5,686,382,618      instructions              #    0.71  insn per cycle
     1,065,835,305      branches                  #  294.537 M/sec
         5,575,268      branch-misses             #    0.52% of all branches

       3.664369150 seconds time elapsed

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

根据perf list中列举的事件，在执行perf stat时携带-e参数即可知道除了上述一般信息外，发生特定事件的次数。比如说想要知道ls命令调用系统调用的次数，则可使用如下命令，可以看到ls的执行，触发了174次的系统调用。（支持tracepoint需要内核对应支持）

perf stat -e raw_syscalls:sys_enter ls
perf.data  perf.txt

 Performance counter stats for 'ls':

               174      raw_syscalls:sys_enter

       0.002700949 seconds time elapsed

1
2
3
4
5
6
7
8
9

三、perf 采样record和采样分析report

perf最重要的功能还是采样功能，Perf工具可以在线程(-t参数)，进程(-p参数)维度进行采样，与采样相关的命令主要是 record,report和annotate。通过perf record 生成 perf.data ，然后再通过 perf report 命令解析生成的data。perf_events的采样是基于事件的采样，采样的周期基于的是一定次数的事件的发生，而不是一定数量的时间周期。每次在采样计数器溢出时进行采样，可以通过-c来指定采样的频率，如果要以固定速率进行采样，就需要指定-F参数。-F参数能指定每秒的采样次数。采样的最核心内容是当前的instruction pointer，即当前程序执行的位置。

perf record
perf report -i perf.data > perf.txt
1
2

使用如上形式可以进行默认的采样，并得到类似如下形式的采样结果，其中samples是采样的次数，而event count是事件发生的实际次数，overhead代表在采样的所占的比例。而command则代表实际的进程或线程（如果命名了特定的线程名）。Shared Object代表对应符号所在的位置，是在特定的库，还是可执行程序，还是在内核（kernel.kallsyms）,Symbol 则自然代表实际被采样到的符号（如果地址是可以识别的话）

 To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 695  of event 'cycles:ppp'
# Event count (approx.): 109033606864305
#
# Overhead  Command          Shared Object       Symbol
# ........  ...............  ..................  ........................................
#
    28.24%  :9770            [kernel.kallsyms]   [k] __d_lookup
    28.24%  perl             [kernel.kallsyms]   [k] get_mem_cgroup_from_mm
    18.92%  perl             [kernel.kallsyms]   [k] native_irq_return_ldt
     4.03%  child_setup      [kernel.kallsyms]   [k] entry_SYSCALL_64_after_swapgs
     4.03%  lsmod            [kernel.kallsyms]   [k] path_openat
     4.03%  smb_status.sh    libc-2.18.so        [.] do_fcntl
     3.53%  pidof            [kernel.kallsyms]   [k] pids_free
     3.53%  smb_status.sh    bash                [.] 0x000000000003e548
     3.09%  pidof            libc-2.18.so        [.] _IO_getc
     2.36%  swapper          [kernel.kallsyms]   [k] update_blocked_averages

···
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

四、perf 采样解析调用栈

perf除了上述的采样形式，还支持解析函数执行的完整调用栈，并得到调用栈中各个环节的cpu消耗，并对位于同一调用栈的各个环节的采样占比进行加总，得到占用cpu比例最高的顶层栈。使用如下命令进行采样

perf record -g --call-graph fp xxx  # xxx 代表具体要执行的命令
perf record -g --call-graph fp -p $(pid)  #采集特定的pid
perf record -g --call-graph fp -a #采集整个系统

perf report > perf.txt
1
2
3
4
5

比如我对本地一个centos系统的采集结果如下（注意采集过程可能会出现很多找不到符号的情况，此为正常现象，可能是在系统构建时，就剔除了部分可执行文件的函数符号，用于裁剪空间）

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 3K of event 'cycles:ppp'
# Event count (approx.): 272061843461905
#
# Children      Self  Command          Shared Object                 Symbol
# ........  ........  ...............  ............................  ..............................................
#
    19.14%     0.00%  swapper          [kernel.kallsyms]             [k] cpu_startup_entry
            |
             --19.14%--cpu_startup_entry
                       |
                        --19.14%--cpuidle_enter
                                  |
                                  |--17.53%--__irqentry_text_start
                                  |          |
                                  |           --17.53%--smp_apic_timer_interrupt
                                  |                     |
                                  |                     |--2.03%--irq_exit
                                  |                     |          |
                                  |                     |          |--1.08%--tick_nohz_irq_exit
                                  |                     |          |          __tick_nohz_idle_enter
                                  |                     |          |
                                  |                     |           --0.95%--__softirqentry_text_start
                                  |                     |                     |
                                  |                     |                      --0.95%--run_timer_softirq
                                  |                     |                                |
                                  |                     |                                 --0.95%--call_timer_fn
                                  |                     |                                           |
                                  |                     |                                            --0.95%--process_timeout
                                  |                     |                                                      wake_up_process
                                  |                     |                                                      try_to_wake_up
                                  |                     |                                                      |
                                  |                     |                                                       --0.95%--select_task_rq_fair

	...
	
    19.14%     0.00%  swapper          [kernel.kallsyms]             [k] cpuidle_enter
            |
            ---cpuidle_enter
               |
               |--17.53%--__irqentry_text_start
               |          |
               |           --17.53%--smp_apic_timer_interrupt
               |                     |
 	

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

这里有几个信息。

其一：整体打印了函数调用的树状结构，并表征了一个符号占用的19.14%具体是由哪些采样的符号组成的。注意即使该符号没有被采样到，他也可能出现在这里，因为可能这个符号调用链的下层调用函数被采样到了，故而这个符号就会体现在这里，而且会把他所有调用到的函数被采样的结果加总起来，得到children这一列。

其二：其中children一列的总和，是可能大于100%的，因为对于每一个采样点，如果能获取到这个采样点完整的调用栈，就会把这个采样点的overhead加总到他的parent symbol的children那一列，而实际的调用栈可能是 A->B->C->D。如果D被采样到了，且比例是1.1%，而A,B,C都未被采样到。则 A,B,C的children那一列均是1.1%,D则self那一列和children那一列都是1.1%。都会呈现在上述report中，故而加总起来会超过100%。

这其实是 perf report 默认携带了 --children参数的结果，在3.16版本以后的内核perf report都是默认携带的–children的参数，会存在children那一列，并对该结果进行计算，以得到占用cpu比例最高的最顶层调用。

如果不希望看到加总的结果，而只希望看到具体的符号被采样的比例，则可以使用如下的命令生成report

perf report --no-children > perf.txt #默认读取perf.data
1

可以得到如下结果，overhead的加总为100%，同时可以看到具体符号的调用栈

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 3K of event 'cycles:ppp'
# Event count (approx.): 272061843461905
#
# Overhead  Command          Shared Object                 Symbol
# ........  ...............  ............................  ..........................................
#
    14.55%  swapper          [kernel.kallsyms]             [k] smp_apic_timer_interrupt
            |
            ---smp_apic_timer_interrupt
               __irqentry_text_start
               cpuidle_enter
               cpu_startup_entry
               start_secondary

    14.55%  perf             [kernel.kallsyms]             [k] flat_send_IPI_mask
    12.93%  nvralarm         [kernel.kallsyms]             [k] copy_page
            |
            ---copy_page
               |
                --12.93%--do_huge_pmd_wp_page
                          handle_mm_fault
                          __do_page_fault
                          do_page_fault
                          page_fault
                          |
                           --12.93%--__reclaim_stacks
                                     0x12fc7

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

参考资料

https://perf.wiki.kernel.org/index.php/Tutorial