2.4 perf 的使用

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

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]
  ..........

 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

Usage: perf probe [<options>] 'PROBEDEF' ['PROBEDEF' ...]
    or: perf probe [<options>] --add 'PROBEDEF' [--add 'PROBEDEF' ...]
    or: perf probe [<options>] --del '[GROUP:]EVENT' ...
    or: perf probe --list [GROUP:]EVENT ...
    or: perf probe [<options>] --line 'LINEDESC'
    or: perf probe [<options>] --vars 'PROBEPOINT'
    or: perf probe [<options>] --funcs

    -a, --add <[EVENT=]FUNC[@SRC][+OFF|%return|:RL|;PT]|SRC:AL|SRC;PT [[NAME=]ARG ...]>
                          probe point definition, where
                GROUP:  Group name (optional)
                EVENT:  Event name
                FUNC:   Function name
                OFF:    Offset from function entry (in byte)
                %return:        Put the probe at function return
                SRC:    Source code path
                RL:     Relative line number from function entry.
                AL:     Absolute line number in file.
                PT:     Lazy expression of line code.
                ARG:    Probe argument (local variable name or
                        kprobe-tracer argument format.)

    -D, --definition <[EVENT=]FUNC[@SRC][+OFF|%return|:RL|;PT]|SRC:AL|SRC;PT [[NAME=]ARG ...]>
                          Show trace event definition of given traceevent for k/uprobe_events.
    -d, --del <[GROUP:]EVENT>
                          delete a probe event.
    -f, --force           forcibly add events with existing name
    -F, --funcs <[FILTER]>
                          Show potential probe-able functions.
    -L, --line <FUNC[:RLN[+NUM|-RLN2]]|SRC:ALN[+NUM|-ALN2]>
    -V, --vars <FUNC[@SRC][+OFF|%return|:RL|;PT]|SRC:AL|SRC;PT>
                        Show accessible variables on PROBEDEF

 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
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87

# 一: 基于 uprobes ，为用户空间库函数添加动态探针
# 想要查看普通应用的函数名称和参数，那么在应用程序的二进制文件中，同样需要包含调试信息。
# 为/bin/bash添加readline探针，获取其返回值，并作为 string 类型返回
$ perf probe -x /bin/bash 'readline'
$ perf probe -x /bin/bash 'readline%return +0($retval):string'
Added new event:
  probe_bash:readline__return (on readline%return in /usr/bin/bash with +0($retval):string)

You can now use it in all perf tools, such as:

        perf record -e probe_bash:readline__return -aR sleep 1


# 查询所有的函数
$ perf probe -x /bin/bash --funcs

# 查询函数的参数
$ perf probe -x /bin/bash -V readline
Available variables at readline
        @<readline+0>
                char*   prompt

# 二: 基于 kprobes，为内核函数添加动态探针
# 1. 通过符号表和寄存器添加 malloc 探针
$ perf probe -x /lib64/libc-2.17.so '--add=malloc'
$ perf probe --del "malloc"
$ perf probe -x /lib64/libc-2.17.so '--add=malloc size=%di'

# 2. 通过 C 扩展
$ yum --enablerepo=base-debuginfo install -y kernel-debuginfo-$(uname -r)
$ perf probe --add tcp_sendmsg
Added new event:
  probe:tcp_sendmsg    (on tcp_sendmsg)

You can now use it in all perf tools, such as:
        # 自动显示使用方式
        perf record -e probe:tcp_sendmsg -aR sleep 1  

# 获取 tcp_sendmsg 的返回值
$ perf probe 'tcp_sendmsg%return $retval'

# 2.1 列出tcp_sendmsg()可用的变量
$ perf probe -V tcp_sendmsg
Available variables at tcp_sendmsg
        @<tcp_sendmsg+0>
                size_t  size
                struct kiocb*   iocb
                struct msghdr*  msg
                struct sock*    sk

# 2.2 添加带参数的探针
$ perf probe --add 'tcp_sendmsg size'

# 2.3 列出tcp_sendmsg()可用的行探测:
$ perf probe -L tcp_sendmsg
<tcp_sendmsg@/mnt/src/linux-3.14.5/net/ipv4/tcp.c:0>
      0  int tcp_sendmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
                        size_t size)
      2  {
                struct iovec *iov;
                struct tcp_sock *tp = tcp_sk(sk);
                struct sk_buff *skb;
      6         int iovlen, flags, err, copied = 0;
      7         int mss_now = 0, size_goal, copied_syn = 0, offset = 0;
                bool sg;
                long timeo;
[...]

# 2.4 检查在第81行有哪些变量可用
$ perf probe -V tcp_sendmsg:81
Available variables at tcp_sendmsg:81
        @<tcp_sendmsg+537>
                bool    sg
                int     copied
                int     copied_syn
                int     flags
                int     mss_now
                int     offset
                int     size_goal
                long int        timeo
                size_t  seglen
                struct iovec*   iov
                struct sock*    sk
                unsigned char*  from

# 2.5. 跟踪第81行，并使用循环中的seglen变量
$ perf probe --add 'tcp_sendmsg:81 seglen'

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

$ perf stat ls
Performance counter stats for 'ls':

          2.164836      task-clock (msec)         #    0.808 CPUs utilized
                51      context-switches          #    0.024 M/sec
                 4      cpu-migrations            #    0.002 M/sec
               333      page-faults               #    0.154 M/sec
           5506056                                #    2.543 GHz
                 0      stalled-cycles-frontend   #    0.00% frontend cycles idle
                 0      stalled-cycles-backend    #    0.00% backend  cycles idle
           6100570      instructions              #    1.11  insns per cycle
           1298744      branches                  #  599.927 M/sec
             18509      branch-misses             #    1.43% of all branches

       0.002679758 seconds time elapsed

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

$ perf stat -d gzip file1

 Performance counter stats for 'gzip file1':

       1610.719530 task-clock                #    0.998 CPUs utilized          
                20 context-switches          #    0.012 K/sec                  
                 0 CPU-migrations            #    0.000 K/sec                  
               258 page-faults               #    0.160 K/sec                  
     5,491,605,997 cycles                    #    3.409 GHz                     [40.18%]
     1,654,551,151 stalled-cycles-frontend   #   30.13% frontend cycles idle    [40.80%]
     1,025,280,350 stalled-cycles-backend    #   18.67% backend  cycles idle    [40.34%]
     8,644,643,951 instructions              #    1.57  insns per cycle        
                                             #    0.19  stalled cycles per insn [50.89%]
     1,492,911,665 branches                  #  926.860 M/sec                   [50.69%]
        53,471,580 branch-misses             #    3.58% of all branches         [51.21%]
     1,938,889,736 L1-dcache-loads           # 1203.741 M/sec                   [49.68%]
       154,380,395 L1-dcache-load-misses     #    7.96% of all L1-dcache hits   [49.66%]
                 0 LLC-loads                 #    0.000 K/sec                   [39.27%]
                 0 LLC-load-misses           #    0.00% of all LL-cache hits    [39.61%]

       1.614165346 seconds time elapsed

 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

# 指定硬件计数器
$ perf stat -e L1-dcache-loads,L1-dcache-load-misses,L1-dcache-stores gzip file1

 Performance counter stats for 'gzip file1':

     1,947,551,657 L1-dcache-loads
                                            
       153,829,652 L1-dcache-misses
         #    7.90% of all L1-dcache hits  
     1,171,475,286 L1-dcache-stores
                                           

       1.538038091 seconds time elapsed

# 使用原始事件
$ perf stat -e cycles,instructions,r80a2,r2b1 gzip file1

 Performance counter stats for 'gzip file1':

     5,586,963,328 cycles                    #    0.000 GHz                    
     8,608,237,932 instructions              #    1.54  insns per cycle        
         9,448,159 raw 0x80a2                                                  
    11,855,777,803 raw 0x2b1                                                   

       1.588618969 seconds time elapsed

# PMCs: counting cycles and frontend stalls via raw specification:
$ perf stat -e cycles -e cpu/event=0x0e,umask=0x01,inv,cmask=0x01/ -a sleep 5

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

# 统计系统调用统计系统调用并打印摘要(非零计数)
$ perf stat -e 'syscalls:sys_enter_*' gzip file1 2>&1 | awk '$1 != 0'

Performance counter stats for 'gzip file1':

                 1 syscalls:sys_enter_utimensat               
                 1 syscalls:sys_enter_unlink                  
                 5 syscalls:sys_enter_newfstat                
             1,603 syscalls:sys_enter_read                    
             3,201 syscalls:sys_enter_write      

1

$ perf record -F 99 -a -g -- sleep 30

1
2

# 每 1000 次收集一次堆栈跟踪
perf record -e L1-dcache-load-misses -c 10000 -ag -- sleep 5

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

# perf record -e sched:sched_process_exec -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.064 MB perf.data (~2788 samples) ]
# perf report -n --sort comm --stdio
[...]
# Overhead       Samples  Command
# ........  ............  .......
#
    11.11%             1    troff
    11.11%             1      tbl
    11.11%             1  preconv
    11.11%             1    pager
    11.11%             1    nroff
    11.11%             1      man
    11.11%             1   locale
    11.11%             1   grotty
    11.11%             1    groff

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

$ perf record -e syscalls:sys_enter_connect -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.057 MB perf.data (~2489 samples) ]
# perf report --stdio
# ========
# Samples: 21  of event 'syscalls:sys_enter_connect'
# Event count (approx.): 21
#
 Overhead  Command       Shared Object                       Symbol
 ........  .......  ..................  ...........................

    52.38%     sshd  libc-2.15.so        [.] __GI___connect_internal
    19.05%   groups  libc-2.15.so        [.] __GI___connect_internal
     9.52%     sshd  libpthread-2.15.so  [.] __connect_internal     
     9.52%     mesg  libc-2.15.so        [.] __GI___connect_internal
     9.52%     bash  libc-2.15.so        [.] __GI___connect_internal

1
2
3
4

$ perf record -e syscalls:sys_enter_connect -ag
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.057 MB perf.data (~2499 samples) ]
$ perf report --stdio

1
2
3
4

$ perf record -e 'skb:consume_skb' -ag
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.065 MB perf.data (~2851 samples) ]
$ perf report

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

# perf buildid-cache --add `which node`
# perf list | grep sdt_node
  sdt_node:gc__done                                  [SDT event]
  sdt_node:gc__start                                 [SDT event]
  sdt_node:http__client__request                     [SDT event]
  sdt_node:http__client__response                    [SDT event]
  sdt_node:http__server__request                     [SDT event]
  sdt_node:http__server__response                    [SDT event]
  sdt_node:net__server__connection                   [SDT event]
  sdt_node:net__stream__end                          [SDT event]
# perf record -e sdt_node:http__server__request -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.446 MB perf.data (3 samples) ]
# perf script
            node  7646 [002]   361.012364: sdt_node:http__server__request: (dc2e69)
            node  7646 [002]   361.204718: sdt_node:http__server__request: (dc2e69)
            node  7646 [002]   361.363043: sdt_node:http__server__request: (dc2e69)

 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
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80

# 1. 添加动态探针
$ perf probe --add tcp_sendmsg
Failed to find path of kernel module.
Added new event:
  probe:tcp_sendmsg    (on tcp_sendmsg)

You can now use it in all perf tools, such as:

	perf record -e probe:tcp_sendmsg -aR sleep 1

# 2. 使用动态探针
$  perf record -e probe:tcp_sendmsg -a -g -- sleep 5

# 3. 输出追踪报告
$ perf report --stdio

# 如果内核有debuginfo (CONFIG_DEBUG_INFO=y)，那么可以从函数中提取内核变量。
# 这是在Linux 3.13.1上检查size_t(整数)的一个简单示例。

# 5.列出tcp_sendmsg()可用的变量
$  perf probe -V tcp_sendmsg
Available variables at tcp_sendmsg
        @<tcp_sendmsg+0>
                size_t  size
                struct kiocb*   iocb
                struct msghdr*  msg
                struct sock*    sk

# 6. 使用变量“size”为tcp_sendmsg()创建一个探针:
$ perf probe --add 'tcp_sendmsg size'

# 7. 跟踪此探针
$ perf record -e probe:tcp_sendmsg -a
$ perf script
# 内核:将显示 tcp_sendmsg()行号和本地变量值
# ========
#
            sshd  1301 [001]   502.424719: probe:tcp_sendmsg: (ffffffff81505d80) size=b0

# 使用debuginfo, perf_events可以为内核函数中的行创建跟踪点。
# 必须安装 kernel-debuginfo 包，或者启用CONFIG_DEBUG_INFO=y
# 8. 列出tcp_sendmsg()可用的行探测:
$ perf probe -L tcp_sendmsg
<tcp_sendmsg@/mnt/src/linux-3.14.5/net/ipv4/tcp.c:0>
      0  int tcp_sendmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
                        size_t size)
      2  {
                struct iovec *iov;
                struct tcp_sock *tp = tcp_sk(sk);
                struct sk_buff *skb;
      6         int iovlen, flags, err, copied = 0;
      7         int mss_now = 0, size_goal, copied_syn = 0, offset = 0;
                bool sg;
                long timeo;
[...]

# 9. 检查在第81行有哪些变量可用
$ perf probe -V tcp_sendmsg:81
Available variables at tcp_sendmsg:81
        @<tcp_sendmsg+537>
                bool    sg
                int     copied
                int     copied_syn
                int     flags
                int     mss_now
                int     offset
                int     size_goal
                long int        timeo
                size_t  seglen
                struct iovec*   iov
                struct sock*    sk
                unsigned char*  from
# 10. 跟踪第81行，并使用循环中的seglen变量
$ perf probe --add 'tcp_sendmsg:81 seglen'
$ perf record -e probe:tcp_sendmsg -a
$ perf script
            sshd  4652 [001] 2082360.931086: probe:tcp_sendmsg: (ffffffff81642ca9) seglen=0x80
   app_plugin.pl  2400 [001] 2082360.970489: probe:tcp_sendmsg: (ffffffff81642ca9) seglen=0x20
        postgres  2422 [000] 2082360.970703: probe:tcp_sendmsg: (ffffffff81642ca9) seglen=0x52
[...]

1
2
3
4
5
6
7
8

# 1. 添加 malloc 探针
$ perf probe -x /lib64/libc-2.17.so '--add=malloc'
$ perf record -e probe_libc:malloc -a
$ perf report -n

# 2. 添加带 size 参数的 malloc 探针
# size 保存的寄存器信息，依赖于你的处理器架构
$ perf probe -x /lib64/libc-2.17.so '--add=malloc size=%di'

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

Usage: perf trace [<options>] [<command>]
    or: perf trace [<options>] -- <command> [<options>]
    or: perf trace record [<options>] [<command>]
    or: perf trace record [<options>] -- <command> [<options>]

    -a, --all-cpus        system-wide collection from all CPUs
    -C, --cpu <cpu>       list of cpus to monitor
    -D, --delay <n>       ms to wait before starting measurement after program start
    -e, --event <event>   event/syscall selector. use 'perf list' to list available events
    -f, --force           don't complain, do it
    -F, --pf <all|maj|min>
                          Trace pagefaults
    -G, --cgroup <name>   monitor event in cgroup name only
    -i, --input <file>    Analyze events in file
    -m, --mmap-pages <pages>
                          number of mmap data pages
    -o, --output <file>   output file name
    -p, --pid <pid>       trace events on existing process id
    --sched           show blocking scheduler events
    --syscalls        Trace syscalls

1

$ perf trace --syscalls ls

1
2
3
4
5
6
7
8
9

# 1. -e 指定多个事件
> sudo perf top -e branch-misses,cycles

# 2. 指定后缀，只跟踪用户态发生的分支预测失败
> sudo perf top -e branch-misses:u,cycles
> sudo perf top -e '{branch-misses,cycles}:u'

# 3. 指定分类
> sudo perf top -e 'cycle' -s comm,pid,dso

1
2
3
4
5
6
7
8

# perf sched -h

 Usage: perf sched [] {record|latency|map|replay|script|timehist}

    -D, --dump-raw-trace  dump raw trace in ASCII
    -f, --force           don't complain, do it
    -i, --input     input file name
    -v, --verbose         be more verbose (show symbol address, etc)

1
2
3
4
5
6
7
8

# perf sched latency

 -----------------------------------------------------------------------------------------------------------------
  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |
 -----------------------------------------------------------------------------------------------------------------
  cat:(6)               |     12.002 ms |        6 | avg:   17.541 ms | max:   29.702 ms | max at: 991962.948070 s
  ar:17043              |      3.191 ms |        1 | avg:   13.638 ms | max:   13.638 ms | max at: 991963.048070 s
  rm:(10)               |     20.955 ms |       10 | avg:   11.212 ms | max:   19.598 ms | max at: 991963.404069 s

1
2
3
4
5
6
7

# perf sched map
                      *A0           991962.879971 secs A0 => perf:16999
                       A0     *B0   991962.880070 secs B0 => cc1:16863
          *C0          A0      B0   991962.880070 secs C0 => :17023:17023
  *D0      C0          A0      B0   991962.880078 secs D0 => ksoftirqd/0:6
   D0      C0 *E0      A0      B0   991962.880081 secs E0 => ksoftirqd/3:28
   D0      C0 *F0      A0      B0   991962.880093 secs F0 => :17022:17022

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

# 1. 导出原始分析数据
> perf record
> perf script # 导出 perf record 中记录的原始数据
> perf script | ./stackcollapse-perf.pl | ./flamegraph.pl > perf-kernel.svg

# List all perf.data events, with customized fields (< Linux 4.1):
perf script -f time,event,trace

# List all perf.data events, with customized fields (>= Linux 4.1):
perf script -F time,event,trace

# List all perf.data events, with my recommended fields (needs record -a; newer kernels):
perf script --header -F comm,pid,tid,cpu,time,event,ip,sym,dso 

# List all perf.data events, with my recommended fields (needs record -a; older kernels):
perf script -f comm,pid,tid,cpu,time,event,ip,sym,dso

# Dump raw contents from perf.data as hex (for debugging):
perf script -D

1
2

perf timechart record ./a.out     # 记录数据
perf timechart                    # 生成 output.svg

1
2
3
4
5
6

# 生成火焰图
git clone https://github.com/brendangregg/FlameGraph  # or download it from github
cd FlameGraph
perf record -F 99 -ag -- sleep 60
perf script | ./stackcollapse-perf.pl > out.perf-folded
cat out.perf-folded | ./flamegraph.pl > perf-kernel.svg