BPF——CPU分析工具

0. CPU工具概览

1. 环境准备

2. CPU性能分析工具

2.1 新进程创建探测工具——execsnoop

execsnoop工具来自BCC工具集，其可以跟踪全系统中的新进程执行信息，利用这个工具我们可以找到消耗大量CPU的短期进程，其用法如下：

# execsnoop
# -x： 找到包含创建失败的新进程
# -n pattern：只输出COMM符合pattern过滤条件的结果
# -l pattern：只输出ARGS符合pattern过滤条件的结果
# --max args argv：输出命令参数个数的上限，默认为20
./execsnoop -x -n pattern

下面是在笔者电脑上使用execsnoop的一个例子：
笔者在terminal 1开启execsnoop程序监听新创建的且进程名称中含有字符gr的进程，然后再terminal 2连接远程Linux，下面是这个过程中系统所创建的进程信息。

[root@bogon ik]# execsnoop -x -n gr
PCOMM            PID     PPID    RET ARGS
grepconf.sh      2341    2331      0 /usr/libexec/grepconf.sh -c
grep             2342    2341      0 /usr/bin/grep -qsi ^COLOR.*none /etc/GREP_COLORS
grep             2348    2331      0 /usr/bin/grep -qi ^COLOR.*none /etc/DIR_COLORS.256color
grepconf.sh      2349    2331      0 /usr/libexec/grepconf.sh -c
grep             2350    2349      0 /usr/bin/grep -qsi ^COLOR.*none /etc/GREP_COLORS
grepconf.sh      2351    2331      0 /usr/libexec/grepconf.sh -c
grep             2352    2351      0 /usr/bin/grep -qsi ^COLOR.*none /etc/GREP_COLORS
grep             2359    2331      0 /usr/bin/grep --color=auto -qs ^PRELINKING=yes /etc/sysconfig/prelink

execsnoop的应用场景：
对于传统的CPU分析工具，比如说top。其对于运行时间十分短的进程是无法做到检测的，在这种场景下就可以考虑使用execsnoop来捕获这些进程。

2.2 进程退出探测工具——exitsnoop

exitsnoop工具来自BCC工具集，其可以跟踪进程退出事件，打印出进程的总运行时常和退出原因，其用法如下：

# exitsnoop
# -p pid: 仅测量该进程
# -t：包含时间错信息
# -x：仅关注程序异常退出
./exitsnoop -t

下面是在笔者电脑上使用exitsnoop的一个例子：
笔者在terminal 1开启exitsnoop程序监听退出的进程，然后再terminal 2关闭远程Linux的ssh连接，下面是这个过程中系统退出的进程信息。

[root@bogon ik]# exitsnoop -t 
TIME-CST     PCOMM            PID     PPID    TID     AGE(s)  EXIT_CODE 
06:18:39.922 bash             2500    2054    2500    6.20    0

2.3 CPU队列长度工具——runqlen

runqlen是一个基于BCC和bpftrace的工具，用来采样CPU运行队列的长度信息，可以统计有多少线程正在等待运行，并以线性直方图的方式输出。其用法如下：

# runqlen
# -C：每个CPU输出一个直方图
# -O：运行队列占有率信息，运行队列不为0的时长百分比
# -T：在输出中包括时间戳信息
./runqlen -C -T

下面是在笔者电脑上使用runqlen的一个例子：
笔者在terminal 1开启runqlen程序监听CPU的使用，这里按照CPU会输出每个CPU队列的长度，这里每个CPU队列都没有阻塞，说明CPU运行状态良好。

[root@bogon ik]# runqlen -C -T
Sampling run queue length... Hit Ctrl-C to end.
05:35:00

cpu = 3
     runqlen       : count     distribution
        0          : 883      |****************************************|

cpu = 6
     runqlen       : count     distribution
        0          : 1064     |****************************************|

cpu = 0
     runqlen       : count     distribution
        0          : 1064     |****************************************|

cpu = 5
     runqlen       : count     distribution
        0          : 1064     |****************************************|

cpu = 1
     runqlen       : count     distribution
        0          : 1003     |****************************************|

cpu = 7
     runqlen       : count     distribution
        0          : 865      |****************************************|

cpu = 2
     runqlen       : count     distribution
        0          : 700      |****************************************|

cpu = 4
     runqlen       : count     distribution
        0          : 1064     |****************************************|

2.4 线程执行时长分析——cpudist

cpudist是一个BCC工具，用来展示每次线程唤醒之后再CPU上执行的时长（不包含线程在队列中的等待信息）分布。其用法如下：

# cpudist
# -m：以毫秒为单位输出
# -O：输出off-cpu时间（非在CPU上执行的时间）
# -P：每个进程打印一个直方图
# -p -pid：仅测量给定的进程
./cpudist

下面是在笔者电脑上使用cpudist的一个例子：
笔者在terminal 1开启cpudist程序监听程序在CPU上的执行时间。这里我们可以看到[4,16]是程序每次在CPU上运行最多的时间。这可能是因为线程超过了CPU调度器分配的运行时长，从而进行了被动上下文切换。

[root@bogon ik]# cpudist 
Tracing on-CPU time... Hit Ctrl-C to end.
     usecs               : count     distribution
         0 -> 1          : 22       |**                                      |
         2 -> 3          : 64       |******                                  |
         4 -> 7          : 386      |****************************************|
         8 -> 15         : 61       |******                                  |
        16 -> 31         : 312      |********************************        |
        32 -> 63         : 89       |*********                               |
        64 -> 127        : 53       |*****                                   |
       128 -> 255        : 26       |**                                      |
       256 -> 511        : 16       |*                                       |
       512 -> 1023       : 63       |******                                  |

2.5 CPU采样工具——profile

profile是一个定时采样调用栈信息并汇报调用栈出现频率信息的BCC工具。默认情况下该工具以49Hz的频率采样所有CPU的用户态和内核态的调用栈。其使用方式如下：

# profile
./profile

下图是在作者的本地linux运行profile执行的情况。

[root@bogon ik]# profile 
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
    __strcasecmp_l_avx
    -                in:imjournal (1468)
        1

    DoDeleteBatchFromQStore
    -                rs:main Q:Reg (1468)
        1

[root@bogon ik]# profile 
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
    _raw_spin_unlock_irqrestore
    _raw_spin_unlock_irqrestore
    fwtable_read32
    gen9_set_dc_state.part.20
    gen9_disable_dc_states
    intel_power_well_enable
    __intel_display_power_get_domain.part.24
    intel_display_power_get
    __gt_unpark
    __intel_wakeref_get_first
    i915_gem_do_execbuffer
    i915_gem_execbuffer2_ioctl
    drm_ioctl_kernel
    drm_ioctl
    __x64_sys_ioctl
    do_syscall_64
    entry_SYSCALL_64_after_hwframe
    __ioctl
    iris_fence_flush
    -                gnome-shell (1598)
        1

    Interpret(JSContext*, js::RunState&)
    js::RunScript(JSContext*, js::RunState&)
    js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct)
    js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>)
    JS_CallFunction(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSFunction*>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>)
    gjs_closure_invoke
    -                gnome-shell (1598)
        1

    [unknown]
    -                flatpak (3003)
        1

    _raw_spin_unlock_irqrestore
    _raw_spin_unlock_irqrestore
    intel_gt_invalidate_tlbs
    __i915_gem_object_unset_pages.part.17
    __i915_gem_object_put_pages
    __i915_gem_free_objects.isra.13
    process_one_work
    worker_thread
    kthread
    ret_from_fork
    -                kworker/u16:1 (2879)
        1

2.6 系统调用统计工具——syscount

syscount是一个bcc和bpftrace工具，用于统计一段时间内系统中系统调用的频次信息。下面是这个工具的用法：

# syscount
# -T TOP：仅打印调用频率最高的N个结果
# -L：打印系统调用的总耗时
# -P：每个进程打印一个直方图
# -p pid：仅测量给定的进程
./syscount -T 5 -L

下面是在笔者电脑上开启syscout统计系统调用的频次信息，这里我们可以看到排名最高的poll这个系统调用，其调用63次的开销和select居然是差不多的，这也说明了poll的系统调用性能比较高。

[root@bogon ik]# syscount -T 5 -L
Tracing syscalls, printing top 5... Ctrl+C to quit.
[06:17:31]
SYSCALL                   COUNT        TIME (us)
poll                         63     16442734.871
select                       10     13211296.193
futex                       596     12234961.939
epoll_wait                  139      5257698.941
ppoll                         8      4225473.030