Using perf-tools in embedded linux

2 minute read

perf-tools is a collection of performance analysis tools based on perf events developed by Brendan Gregg, perf-tools are widely used on linux server and can alose be used in embedded field with some extra works described below.

Preparation

bash

wget -c https://ftp.gnu.org/gnu/bash/bash-5.2.21.tar.gz
./configure --host=mipsel-linux
make

awk

wget -c https://ftp.gnu.org/gnu/gawk/gawk-5.3.0.tar.xz
./configure --host=mipsel-linux
make

ln -s /bin/gawk /bin/awk

Build perf

See this post

The following libraries should be copied to target rootfs:

/usr/local/mips/mipsel-buildroot-linux-gnu/mipsel-buildroot-linux-gnu/sysroot/usr/lib/libunwind.so.8
/usr/local/mips/mipsel-buildroot-linux-gnu/mipsel-buildroot-linux-gnu/sysroot/usr/lib/libunwind-mips.so.8
/usr/local/mips/mipsel-buildroot-linux-gnu/mipsel-buildroot-linux-gnu/sysroot/usr/lib/libdw.so.1
/usr/local/mips/mipsel-buildroot-linux-gnu/mipsel-buildroot-linux-gnu/sysroot/usr/lib/libbfd-2.38.so
/usr/local/mips/mipsel-buildroot-linux-gnu/mipsel-buildroot-linux-gnu/sysroot/usr/lib/libopcodes-2.38.so

Build kernel

Verified with linux-6.1.68

CONFIG_DEBUG_FS=y
CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y    # iosnoop
CONFIG_FTRACE_SYSCALLS=y    # killsnoop
CONFIG_KPROBES=y            # opensnoop
CONFIG_MODULES=y
CONFIG_FUNCTION_PROFILER=y  # funccount
CONFIG_PERF_EVENTS=y        # syscount
CONFIG_BPF_SYSCALL=y        # syscount

Example

cachestat

# cachestat
Counting cache functions... Output every 1 seconds.
    HITS   MISSES  DIRTIES    RATIO   BUFFERS_MB   CACHE_MB
     436        0        0   100.0%            0         16
     436        0        0   100.0%            0         16
     437        0        0   100.0%            0         16
     436        0        0   100.0%            0         16
     436        0        0   100.0%            0         16
     436        0        0   100.0%            0         16

funccount ‘vfs*’

# funccount 'vfs*'
Tracing "vfs*"... Ctrl-C to end.
^C
FUNC                              COUNT
vfs_getxattr                          1
vfs_getxattr_alloc                    1
vfs_ioctl                             1
vfs_setpos                            1
vfs_llseek                            2
vfs_write                             2
vfs_getattr                           3
vfs_iter_read                         4
vfs_get_link                          5
vfs_open                             11
vfs_getattr_nosec                    23
vfs_read                             24
vfs_statx                            33

Ending tracing...

syscount

# syscount -cd 5 -t 10
Tracing for 5 seconds. Top 10 only...
SYSCALL              COUNT
clock_gettime            2
close                    2
execve                   2
munmap                   2
sched_setaffinity        3
mprotect                 4
statx                    4
openat                   5
mips_mmap2               6
ioctl                  614

functrace

# functrace 'vfs_read'
Tracing "vfs_read"... Ctrl-C to end.
           <...>-447   [001] ...1    79.649495: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649573: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649584: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649608: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649618: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649624: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.649628: vfs_read <-kernel_read
           <...>-447   [001] ...1    79.650745: vfs_read <-ksys_read
             top-437   [000] ...1    82.387025: vfs_read <-ksys_read
             top-437   [000] ...1    82.387215: vfs_read <-ksys_read
             top-437   [000] ...1    82.387347: vfs_read <-ksys_read
             top-437   [000] ...1    82.387474: vfs_read <-ksys_read
             top-437   [000] ...1    82.387592: vfs_read <-ksys_read
             top-437   [000] ...1    82.387907: vfs_read <-ksys_read
^C
Ending tracing...

kprobe

# kprobe p:do_sys_open
Tracing kprobe do_sys_open. Ctrl-C to end.
             top-471   [001] ...1  1866.367379: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367438: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367484: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367531: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367574: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367614: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] .n.1  1866.367655: do_sys_open: (do_sys_open+0x0/0x250)
             top-471   [001] ...1  1866.367947: do_sys_open: (do_sys_open+0x0/0x250)
^C
Ending tracing...

opensnoop

# opensnoop
Tracing open()s. Ctrl-C to end.
COMM             PID      FD FILE
awk: cmd. line:19: warning: regexp escape sequence `\"' is not a known regexp operator
awk              480     0x2 /etc/ld.so.cache
cat              481     0x2 /etc/ld.so.cache
awk              480     0x2 /lib/tls/mips/libm.so.6
cat              481     0x2 /lib/tls/mips/libc.so.6
awk              480     0x2 /lib/tls/libm.so.6
cat              481     0x2 /lib/tls/libc.so.6
awk              480     0x2 /lib/mips/libm.so.6
cat              481     0x2 /lib/mips/libc.so.6
awk              480     0x3 /lib/libm.so.6
cat              481     0x3 /lib/libc.so.6
awk              480     0x3 /lib/libc.so.6
cat              481     0x3 trace_pipe
top              471     0x3 /proc
top              471     0x4 /proc/1/stat
top              471     0x4 /proc/2/stat
top              471     0x4 /proc/3/stat
[...]
^C
Ending tracing...

perf-stat-hist

# perf-stat-hist -b 10 syscalls:sys_exit_read ret 30
Tracing syscalls:sys_exit_read, specified buckets, for 30 seconds...

            Range          : Count    Distribution
              -> 9         : 282      |###################################   |
           10 ->           : 307      |######################################|

bitesize

# bitesize
Tracing block I/O size (bytes), until Ctrl-C...
^C
            Kbytes         : I/O      Distribution
              -> 0.9       : 0        |                                      |
          1.0 -> 7.9       : 0        |                                      |
          8.0 -> 63.9      : 0        |                                      |
         64.0 -> 127.9     : 0        |                                      |
        128.0 ->           : 0        |                                      |