perf基本使用功能

233333

发布于 2022-09-26 15:34:12

7620

发布于 2022-09-26 15:34:12

文章被收录于专栏：linux驱动个人学习linux驱动个人学习

perf top

用于实时显示当前系统的性能统计信息。该命令主要用来观察整个系统当前的状态，比如可以通过查看该命令的输出来查看当前系统最耗时的内核函数或某个用户进程

再往下看是一个表格式样的数据，每一行包含四列，分别是：

第一列 Overhead ，是该符号的性能事件在所有采样中的比例，用百分比来表示。

第二列 Shared ，是该函数或指令所在的动态共享对象（Dynamic Shared Object），如内核、进程名、动态链接库名、内核模块名等。

第三列 Object ，是动态共享对象的类型。比如 [.] 表示用户空间的可执行程序、或者动态链接库，而 [k] 则表示内核空间。

最后一列 Symbol 是符号名，也就是函数名。当函数名未知时，用十六进制的地址来表示。

perf stat

通过概括精简的方式提供被调试程序运行的整体情况和汇总数据

Task-clock-msecs：CPU 利用率，该值高，说明程序的多数时间花费在 CPU 计算上而非 IO。
Context-switches：进程切换次数，记录了程序运行过程中发生了多少次进程切换，频繁的进程切换是应该避免的。
Cache-misses：程序运行过程中总体的 cache 利用情况，如果该值过高，说明程序的 cache 利用不好
CPU-migrations：表示进程 t1 运行过程中发生了多少次 CPU 迁移，即被调度器从一个 CPU 转移到另外一个 CPU 上运行。
Cycles：处理器时钟，一条机器指令可能需要多个 cycles，
Instructions: 机器指令数目。
IPC：是 Instructions/Cycles 的比值，该值越大越好，说明程序充分利用了处理器的特性。
Cache-references: cache 命中的次数
Cache-misses: cache 失效的次数。

注：通过指定 -e 选项，您可以改变 perf stat 的缺省事件

perf probe

perf-porbe 定义新的动态的tracepoint 大致用法：

perf probe [options] --add='PROBE' [...]
perf probe [options] PROBE
perf probe [options] --del = 
perf probe --list
perf porbe --vars

这条命令

1）在不借助debuginfo的前提下，使用符号和寄存器信息定义动态的tracepoint；

2）借助debuginfo的信息，使用c表达式来动态地确定出

先看下kprobe是否打开

root@ecs-148531:/home/i# sudo cat /boot/config-$(uname -r) | grep -i kprobe
CONFIG_KPROBES=y
CONFIG_KPROBES_ON_FTRACE=y
CONFIG_HAVE_KPROBES=y
CONFIG_HAVE_KPROBES_ON_FTRACE=y
CONFIG_KPROBE_EVENTS=y
# CONFIG_KPROBE_EVENTS_ON_NOTRACE is not set
CONFIG_BPF_KPROBE_OVERRIDE=y
# CONFIG_KPROBES_SANITY_TEST is not set
# CONFIG_SAMPLE_KPROBES is not set
root@ecs-148531:/home/i#

然后比如打开kprobe追踪 tcp_sendmsg

root@ecs-148531:/home/i# sudo perf probe --add tcp_sendmsg -f
Added new event:
  probe:tcp_sendmsg_1  (on tcp_sendmsg)

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

        perf record -e probe:tcp_sendmsg_1 -aR sleep 1

root@ecs-148531:/home/i#

记录追踪的数据到perf.data文件

root@ecs-148531:/home/i# perf record -e probe:tcp_sendmsg_1 -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.245 MB perf.data (12 samples) ]
root@ecs-148531:/home/i# ls perf.data
perf.data

查看数据

root@ecs-148531:/home/i# perf script
            sshd 273406 [001] 19292974.395979: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.397396: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.397546: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.399462: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.417027: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.417365: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.417518: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.418329: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.418507: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.421884: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.422054: probe:tcp_sendmsg_1: (ffffffff869ca330)
            sshd 273406 [001] 19292974.476894: probe:tcp_sendmsg_1: (ffffffff869ca330)

再跟踪一个函数do_sys_open

i@ecs-148531:~$ sudo perf probe --add do_sys_open -f
Added new event:
  probe:do_sys_open_2  (on do_sys_open)

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

        perf record -e probe:do_sys_open_2 -aR sleep 1

i@ecs-148531:~$ sudo perf record -e probe:do_sys_open_2 -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.240 MB perf.data (24 samples) ]
i@ecs-148531:~$ sudo perf script
            perf 489024 [001] 19294363.211799: probe:do_sys_open_2: (ffffffff862db420)
           sleep 489027 [000] 19294363.212219: probe:do_sys_open_2: (ffffffff862db420)
           sleep 489027 [000] 19294363.212233: probe:do_sys_open_2: (ffffffff862db420)
           sleep 489027 [000] 19294363.212468: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446651: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446742: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446788: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446855: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446919: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.446973: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447024: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447075: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447134: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447185: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447237: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447287: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447338: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447388: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447439: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447490: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447541: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447593: probe:do_sys_open_2: (ffffffff862db420)
       hostguard 471124 [000] 19294363.447644: probe:do_sys_open_2: (ffffffff862db420)
        ilogtail 1294671 [000] 19294364.153081: probe:do_sys_open_2: (ffffffff862db420)
i@ecs-148531:~$

接下来看下用uprobe来trace userland的函数，比如

#perf probe -x /lib/x86_64-linux-gnu/libc.so.6 malloc

这个trace libc.so这个动态库的malloc调用。我们可以看到，上述命令已经生效。

root@ecs-148531:/home/i# cat /sys/kernel/debug/tracing/uprobe_events
p:probe_libc/malloc /usr/lib/x86_64-linux-gnu/libc-2.31.so:0x000000000009d260

开始记录

root@ecs-148531:/home/i# perf record -e probe_libc:malloc -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.264 MB perf.data (237 samples) ]
root@ecs-148531:/home/i#

察看结果

   #perf script 
     sleep 495936 [001] 19347149.645089: probe_libc:malloc: (7f86f8af9260)
     mosh-server 489795 [001] 19347149.976167: probe_libc:malloc: (7f6cfe66b260)
     mosh-server 489795 [001] 19347149.976178: probe_libc:malloc: (7f6cfe66b260)

perf trace

perf trace有类似于strace功能，可以实时监控程序的系统调用：

# perf trace ./a.out
 0.032 ( 0.002 ms): a.out/7673 brk(                                                                  ) = 0x1e6b000
 0.051 ( 0.005 ms): a.out/7673 access(filename: 0xb7c1cb00, mode: R                                  ) = -1 ENOENT No such file or directory
 0.063 ( 0.005 ms): a.out/7673 open(filename: 0xb7c1a7b7, flags: CLOEXEC                             ) = 3
 0.070 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bc80                                  ) = 0
 0.073 ( 0.004 ms): a.out/7673 mmap(len: 38436, prot: READ, flags: PRIVATE, fd: 3                    ) = 0x7f18b7e15000
 0.079 ( 0.001 ms): a.out/7673 close(fd: 3                                                           ) = 0
 0.087 ( 0.005 ms): a.out/7673 open(filename: 0xb7e21ec0, flags: CLOEXEC                             ) = 3
 0.093 ( 0.003 ms): a.out/7673 read(fd: 3, buf: 0x7ffffb72be28, count: 832                           ) = 832
 0.099 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bcc0                                  ) = 0
 0.102 ( 0.003 ms): a.out/7673 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f18b7e13000
 0.110 ( 0.004 ms): a.out/7673 mmap(len: 2283024, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3   ) = 0x7f18b79cf000
 0.116 ( 0.007 ms): a.out/7673 mprotect(start: 0x7f18b79fc000, len: 2093056                          ) = 0
 0.125 ( 0.005 ms): a.out/7673 mmap(addr: 0x7f18b7bfb000, len: 8192, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 180224) = 0x7f18b7bfb000
 0.142 ( 0.002 ms): a.out/7673 close(fd: 3                                                           ) = 0
 0.153 ( 0.006 ms): a.out/7673 open(filename: 0xb7e134c0, flags: CLOEXEC                             ) = 3
 0.161 ( 0.003 ms): a.out/7673 read(fd: 3, buf: 0x7ffffb72bdf8, count: 832                           ) = 832
 0.165 ( 0.002 ms): a.out/7673 fstat(fd: 3, statbuf: 0x7ffffb72bc90                                  ) = 0
 0.169 ( 0.005 ms): a.out/7673 mmap(len: 2216432, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3   ) = 0x7f18b77b1000
......

本文参与腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。

原始发表：2022-08-28，如有侵权请联系 cloudcommunity@tencent.com 删除

data