8

Linux tracing/profiling 基础:符号表、调用栈、perf/bpftrace 示例等(2022)

 2 years ago
source link: http://arthurchiao.art/blog/linux-tracing-basis-zh/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

Linux tracing/profiling 基础:符号表、调用栈、perf/bpftrace 示例等(2022)

Published at 2022-07-18 | Last Update 2022-07-18

整理一些 tracing/profiling 笔记, 内容主要来自 Practical Linux tracing 系列几篇文章。


1.1 热点与调用栈分析(perf record/report/script

perf 能够跟踪记录内核及应用程序的执行状态,

$ perf record -a -g -- sleep 5
[ perf record: Woken up 10 times to write data ]
[ perf record: Captured and wrote 4.636 MB perf.data (24700 samples) ]

生成的信息保存在 perf.data 中,然后通过 perf report/script,就可以分析性能和调用栈。例如,

  1. perf report 查看看哪些函数占用的 CPU 最多

     $ perf report
     Samples: 24K of event 'cycles', Event count (approx.): 4868947877
       Children      Self  Command   Shared Object        Symbol
     +   17.08%     0.23%  swapper   [kernel.kallsyms]    [k] do_idle
     +    5.38%     5.38%  swapper   [kernel.kallsyms]    [k] intel_idle
     +    4.21%     0.02%  kubelet   [kernel.kallsyms]    [k] entry_SYSCALL_64_after_hwframe
     +    4.08%     0.00%  kubelet   kubelet              [.] k8s.io/kubernetes/vendor/github.com/google/...
     +    4.06%     0.00%  dockerd   dockerd              [.] net/http.(*conn).serve
     +    3.96%     0.00%  dockerd   dockerd              [.] net/http.serverHandler.ServeHTTP
     ...
    

    这是一个交互式的窗口,可以选中具体函数展开查看详情。

  2. perf script 展示采集到的事件及其调用栈

     $ perf script
     perf 44564 [000] 743873.947847:          1   cycles:
             ffffffffa786af46 native_write_msr+0x6 ([kernel.kallsyms])
             ffffffffa780d92f __intel_pmu_enable_all.constprop.0+0x3f ([kernel.kallsyms])
             ffffffffa79fb3a9 event_function+0x89 ([kernel.kallsyms])
             ffffffffa79f48ee remote_function+0x3e ([kernel.kallsyms])
             ffffffffa7933199 generic_exec_single+0x59 ([kernel.kallsyms])
             ffffffffa79332ac smp_call_function_single+0xdc ([kernel.kallsyms])
             ...
    
  3. perf script 的输出重定向到 perl 脚本做进一步处理,就得到了著名的火焰图

     $ perf script | ./stackcollapse-perf.pl | ./flamegraph.pl > result.svg
    

这些都是基于 tracing 功能。

1.2 符号(symbols)

Tracing 功能的基础是符号(symbols),即目标文件中的函数信息。 Symbols 对 kprobe/uprobe event tracing 至关重要,因为知道函数名字才能跟踪。来看两个例子:

  1. 查看 grep 这个最常用的命令(可执行文件)中包含哪些符号:

     $ readelf -s `which grep`
     Symbol table '.dynsym' contains 137 entries:
        Num:    Value          Size Type    Bind   Vis      Ndx Name
          0: 0000000000000000     0 NOTYPE  LOCAL  DEFAULT  UND
          1: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND __ctype_toupper_loc@GLIBC_2.3 (2)
          2: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND __uflow@GLIBC_2.2.5 (3)
          3: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND getenv@GLIBC_2.2.5 (3)
          ...
    
  2. 查看内核符号表:

     $ cat /proc/kallsyms | egrep ' (t|T) ' | head
     0000000000000000 T startup_64
     0000000000000000 T secondary_startup_64
     0000000000000000 t verify_cpu
     0000000000000000 T sev_verify_cbit
     0000000000000000 T start_cpu0
     0000000000000000 T __startup_64
     ...
    

以上看出,符号可以位于目标文件中,也可以存放在单独的文件

1.3 小结

Symbols 与 gcc -g 产生的 debug info 并不是一个东西。 下面我们通过一个简单例子来看一下。

2 极简程序 hello-world:探究符号

2.1 C 源码

C 程序 hello-world.c

#include <stdio.h>
#include <unistd.h>
void hello() {
    printf("Hello, world!\n");
    sleep(1);
}

int main() {
    hello();
}

2.2 编译成目标文件(不带 -g

$ gcc hello-world.c -o hello-world

file 查看目标文件信息:

$ file hello-world
hello-world: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked (uses shared libs), not stripped

可以看到是可执行文件,后面会解释 not stripped 是什么意思。

2.3 查看目标文件(objdump/readelf

objdump 查看可执行文件(目标文件) hello-world 中的各 section:

# -h/--headers
$ objdump -h hello
hello-world:     file format elf64-x86-64

Sections:
Idx Name          Size      VMA               LMA               File off  Algn
  0 .interp       0000001c  0000000000400238  0000000000400238  00000238  2**0
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
  4 .dynsym       00000078  00000000004002b8  00000000004002b8  000002b8  2**3
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
 ...
 24 .data         00000004  0000000000601030  0000000000601030  00001030  2**0
                  CONTENTS, ALLOC, LOAD, DATA
 25 .bss          00000004  0000000000601034  0000000000601034  00001034  2**0
                  ALLOC
 26 .comment      0000002d  0000000000000000  0000000000000000  00001034  2**0
                  CONTENTS, READONLY

确认其中并没有 debug section:

$ objdump -h hello | grep debug
#<nothing found>

readelf -s 读取 symbols,确认其中有我们定义的 hello() 方法:

# -s/--symbols
$ readelf -s hello-world | fgrep hello

Symbol table '.dynsym' contains 5 entries:  # 动态符号表
   Num:    Value          Size Type    Bind   Vis      Ndx Name
     0: 0000000000000000     0 NOTYPE  LOCAL  DEFAULT  UND
     1: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND puts@GLIBC_2.2.5 (2)
     2: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND __libc_start_main@GLIBC_2.2.5 (2)
     3: 0000000000000000     0 NOTYPE  WEAK   DEFAULT  UND __gmon_start__
     4: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND sleep@GLIBC_2.2.5 (2)

Symbol table '.symtab' contains 66 entries: # 局部(local)符号表
   Num:    Value          Size Type    Bind   Vis      Ndx Name
     0: 0000000000000000     0 NOTYPE  LOCAL  DEFAULT  UND
     1: 0000000000400238     0 SECTION LOCAL  DEFAULT    1
    ...
    53: 000000000040055d    26 FUNC    GLOBAL DEFAULT   14 hello  # hello() 函数
    ...
    62: 0000000000400577    16 FUNC    GLOBAL DEFAULT   14 main
    64: 0000000000000000     0 FUNC    GLOBAL DEFAULT  UND sleep@@GLIBC_2.2.5
    65: 0000000000400400     0 FUNC    GLOBAL DEFAULT   11 _init

2.4 用 bpftrace 跟踪 hello-world 程序执行

执行 hello-world 程序, 用 bpftrace 来跟踪这个方法,注意这是用户空间函数,因此用 uprobe,

$ bpftrace -e 'uprobe:./hello-world:hello {printf("%s",ustack)}' -c ./hello-world
Attaching 1 probe...
hello world!

        hello+0
        __libc_start_main+245

2.5 小结

这个例子可以看出,function tracing 只需要 symbols,不需要 debug symbols(gcc -g)。 那 debug info 有什么用呢?在回答这个问题之前,我们先更深入了解下常规 symbols。

3.1 动态符号(.dynsym)vs. 局部符号(.symtab

Symbols 有两种,都是 readelf -s 输出中的 FUNC 类型,

  • .dynsym:动态符号,可以被其他程序使用;
  • .symtab:“局部”符号,只能被该可执行程序自己使用。

3.2 stripped vs. not stripped

通常情况下,生成可执行文件时,“局部”符号会被去掉,(以减小 binary size), 然后通过单独的 xx-dbg/xx-dbgsym 包来提供这些符号 (也就是放到独立的文件,按需下载和使用)。

先看个正常的,

$ readelf -s hello-world | grep "Symbol table"
Symbol table '.dynsym' contains 8 entries:
Symbol table '.symtab' contains 67 entries:

两个符号表里面的函数都可以跟踪。再看 nginx,就去掉了 local:

$ readelf -s `which nginx` | grep 'Symbol table'
Symbol table '.dynsym' contains 1077 entries: # 只能跟踪这里面的 FUNC 了

3.2.1 手动去掉局部符号(strip -s

可以用命令 strip手动去掉局部符号表

$ strip -s ./hello-world # 原地 strip,直接修改可执行文件
$ readelf -s hello-world | grep "Symbol table"
Symbol table '.dynsym' contains 8 entries:

如果对比 strip 前面的文件类型变化:

$ file hello # strip 之前的可执行文件
hello: ELF 64-bit LSB executable, x86-64, dynamically linked, ..., not stripped
$ strip -s hello
$ file hello # strip 之后的可执行文件
hello: ELF 64-bit LSB executable, x86-64, dynamically linked, ..., stripped

3.2.2 再次用 bpftrace 跟踪局部函数

strip 之后再测试用 bpftrace 来跟踪局部函数,就不行了:

$ bpftrace -e 'uprobe:./hello:hello {printf("%s",ustack)}' -c ./hello
No probes to attach

4 Debug symbol(gcc -g):DWARF 格式

对 symbols 有了一个基本了解之后,现在我们重新回到 debug symbols。

既然对于跟踪来说 symbols 就够用了,那 debug symbols 有什么用呢?

4.1 Debug symbols 的用途或功能

Debug symbol 是 dwarf 格式信息 。 How debuggers work: Part 3 - Debugging information

4.1.1 功能一:将内存地址映射到具体某行源代码

首先带 -g 重新编译,生成的 binary 带 debug 符号,

$ gcc hello-world.c -g -o hello-world
$ objdump --dwarf=decodedline hello-world

hello:     file format elf64-x86-64

Decoded dump of debug contents of section .debug_line:

CU: symbol.c:
File name           Line number    Starting address
hello-world.c                 3            0x40055d
hello-world.c                 4            0x400561
hello-world.c                 5            0x40056b
hello-world.c                 6            0x400575
hello-world.c                 7            0x400577
hello-world.c                 8            0x40057b
hello-world.c                 9            0x400585

第二列和第三列分别是源代码行号和在内存中的地址。例如,下面这行表示源码中的第三行代码 对应的内存地址为 0x40055d

File name           Line number    Starting address
hello-world.c                 3            0x40055d

readelf 输出中搜一下地址 0x40055d

$ readelf -s hello | grep 40055d
Symbol table '.symtab' contains 71 entries:
   Num:    Value          Size Type    Bind   Vis      Ndx Name
    ...
    58: 000000000040055d    26 FUNC    GLOBAL DEFAULT   14 hello

最后一列是函数名,可以看到这个地址对应的是 hello() 函数; 我们对照源文件看下,正是第 3 行:

$ cat -n hello-world.c
1  #include <stdio.h>
2  #include <unistd.h>
3  void hello() {
4      printf("hello world!\n");
5      sleep(1);
6  }
7  int main() {
8      hello();
9  }

4.1.2 功能二:调用栈展开(stack unwinding)

stack-unwind.c

#include <stdio.h>
#include <unistd.h>
void func_c() {
    int msec=1;
    printf("%s","Hello world from C\n");
    usleep(10000*msec);
}
void func_b() {
    printf("%s","Hello from B\n");
    func_c();
}
void func_a() {
    printf("%s","Hello from A\n");
    func_b();
}
int main() {
    func_a();
}

编译,注意带 -g

$ gcc stack-unwind.c -g -o stack-unwind

设置 perf 跟踪 func_c() 函数的执行,

# -x, --exec <executable|path>
$ perf probe -x ./stack-unwind 'func_c'
Added new event:
  probe_stack:func_c   (on func_d in /root/xxx/stack-unwind)

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

        perf record -e probe_stack:func_c -aR sleep 1

执行应用程序,并用 perf 记录,注意这里选择的调用图(call graph)类型是 dwarf

$ perf record -e probe_stack:func_c -aR -g --call-graph dwarf ./stack-unwind
Hello from A
Hello from B
Hello world from C
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.097 MB perf.data (1 samples) ]

查看调用栈:

$ perf script
stack-unwind 134641 [044] 748089.345628: probe_stack:func_c: (40055d)
                  40055d func_c+0x0  (/root/xxx/stack-unwind)
                  40059f func_b+0x17 (/root/xxx/stack-unwind)
                  4005b9 func_a+0x17 (/root/xxx/stack-unwind)
                  4005c9 main+0xd    (/root/xxx/stack-unwind)
            7f926d98b554 __libc_start_main+0xf4 (/usr/lib64/libc-2.17.so)
                  400498 _start+0x28 (/root/xxx/stack-unwind)

4.2 DWARF 格式存在的一些问题

  • 占用空间通常很大;
  • 基于 BPF 的工具(例如 bpftrace)与它兼容性不好,无法展开 DWARF 类型的调用栈;

    BPF 工具一般使用另一种 stack unwinding 技术:frame pointer(帧指针)。 这是 perf 使用的默认 stack walking 方式,也是 bcc/bpftrace 目前支持的唯一方式。

5 调用栈展开(方式二):frame pointer

5.1 基本原理

简单来说,

  • 每个 stack trace (或称 activation records 或 call stacks) 包含很多 frames,这 些 frames 以 LIFO(后进先出)方式存储。这与栈的工作原理一样,stack frames 由此得名;
  • 每个 frame 包含了一个函数执行时的状态信息(参数所在的内存区域、局部变量、返回值等等);
  • Frame pointer 是指向 frame 内存地址的指针,

接下来通过一些基于汇编、offset、CPU 寄存器等黑科技,就能构建出一个完整的函数调用栈。 刚才提到,这是 perf 的默认 stack unwinding 方式,也是 bcc/bpftrace 目前支持的唯一方式。 但与 perf 不同,bcc/bpftrace 用自己的 BPF helper 和 map storage 来存储栈信息。

5.2 例子

重新编译,去掉 -g 参数(留着也行,但 frame pointer 不会使用 dwarf 信息),

$ gcc stack-unwind.c -o stack-unwind

指定 --call-graph fp

$ perf record -e probe_stack:func_c -aR -g --call-graph fp ./stack-unwind
Hello from A
Hello from B
Hello world from C
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.402 MB perf.data ]

用 bpftrace 跟踪,

$ bpftrace -e 'uprobe:./stack-unwind:func_c {printf("%s\n", ustack); }' -c ./stack-unwind
Attaching 1 probe...
Hello from A
Hello from B
Hello world from C

        func_c+0
        func_a+24
        main+14
        __libc_start_main+245

5.3 存在的问题:默认编译参数 -fomit-frame-pointer

出于优化目的,很多软件在正式编译时都会指定 -fomit-frame-pointer, 导致无法使用 frame-pointer 这种 stack walking 方式。具体看下效果:

$ gcc stack-unwind.c -o stack-unwind -fomit-frame-pointer

$ bpftrace -e 'uprobe:./stack-unwind:func_c {printf("%s\n", ustack); }' -c ./stack-unwind
Attaching 1 probe...
Hello from A
Hello from B
Hello world from C

        func_c+0

很多系统上这都是默认选项,尤其是性能敏感的软件,例如 C 标准库、JVM。 很多时候用 frame pointer 方式展开调用栈时,会看到 unknown symbol 之类的错误,就是因为这个原因。

在 C 世界中,-g-fno-omit-frame-pointer 要更常用,因此很多场景下都是可以拿到 DWARF 信息的。

6 Profiling & tracing

有了以上基础,就可以对系统或程序进行 profiling & tracing 了。

6.1 Perf profiling

最简单方式:

$ perf record -a -g -F 99 -- sleep 10
$ perf script # perf report

每秒采样 99 次,持续 10 秒。

提高采集频率:

$ echo {rate} > /proc/sys/kernel/perf_event_max_sample_rate

注意,这将对 CPU、磁盘 IO 等有显著影响。

6.2 bpftrace profiling

bpftrace 之类的工具也能做一些 profiling,但底层还是用的 perf 数据源perf_event_output() )

$ bpftrace -e 'profile:hz:99 {@[kstack]=count();}'
Attaching 1 probe...
^C

@[
    poll_idle+89
    cpuidle_enter_state+137
    cpuidle_enter+41
    do_idle+468
    cpu_startup_entry+25
    start_secondary+275
    secondary_startup_64_no_verify+194
]: 1
@[
    __d_lookup_rcu+60
    lookup_fast+69
    walk_component+67
    link_path_walk.part.0+545
    path_openat+197
    do_filp_open+145
    do_sys_openat2+546
    do_sys_open+68
    do_syscall_64+51
    entry_SYSCALL_64_after_hwframe+68
]: 1
...

6.3 bpftrace event tracing

Kernel tracing

在一个窗口用 bpftrace 跟踪 open() 系统调用,如果被打开的文件是 hello-world.c,就打印一条消息出来:

$ bpftrace -e 'tracepoint:syscalls:sys_enter_open,tracepoint:syscalls:sys_enter_openat {
    $name = str(args->filename);
    if ( $name == "hello-world.c" ) { printf("Somebody touched my file!\n"); }
}'
Attaching 2 probes...

然后在另一个窗口中用 file 查看这个文件的信息,这会触发 open() 系统调用:

$ file symbol.c
symbol.c: C source, ASCII text

会看到 bpftrace 的窗口打印以下信息:

Somebody touched my file!

另一个例子:

$ bpftrace -e 'tracepoint:syscalls:sys_enter_execve { printf("%-10u %-5d ", elapsed / 1000000, pid); join(args->argv); }'
Attaching 1 probe...
2244       489603 /opt/cni/bin/cilium-cni
2976       489610 runc --version
2983       489616 runc --version
2989       489622 docker-init --version
...

另一个例子:查看内核收包调用栈

$ bpftrace -e 'kprobe:netif_receive_skb_list_internal {printf("%s\n",kstack);}'

        netif_receive_skb_list_internal+1
        gro_normal_list.part.0+25
        napi_complete_done+104
        tg3_poll_msix+331
        net_rx_action+322
        __softirqentry_text_start+223
        asm_call_on_stack+18
        do_softirq_own_stack+55
        irq_exit_rcu+202
        common_interrupt+116
        asm_common_interrupt+30
        cpuidle_enter_state+218
        cpuidle_enter+41
        do_idle+468
        cpu_startup_entry+25
        start_secondary+275
        secondary_startup_64_no_verify+194

User space tracing

第一个例子:假设 libwebp 有漏洞,查看某个服务(PID 25760)是否使用了这个动态库:

$ grep libwebp /proc/25760/maps
7f7bc6af3000-7f7bc6af6000 r--p 00000000 09:01 38281904                   /usr/lib/x86_64-linux-gnu/libwebp.so.6.0.2

看到有使用这个库,接下来跟踪这个动态库,看是否真正有函数调用:

$ bpftrace -e 'uprobe:/usr/lib/x86_64-linux-gnu/libwebp.so.6.0.2:* {time("%H:%M:%S "); printf("%s %d\n",comm,pid);}' | tee /tmp/libwebp.trace

第二个例子:追踪 DNS 问题:首先找到相关函数,

$ for x in `ldd /usr/sbin/named | awk '{print $3}'`; do objdump -T $x | grep dns_ncache && echo $x; done
00000000000a2cc0 g    DF .text 000000000000001e  Base        dns_ncache_add
00000000000a2ce0 g    DF .text 0000000000000022  Base        dns_ncache_addoptout
00000000000a2d10 g    DF .text 000000000000093e  Base        dns_ncache_towire
00000000000a3650 g    DF .text 0000000000000441  Base        dns_ncache_getrdataset
00000000000a4040 g    DF .text 0000000000000392  Base        dns_ncache_current
00000000000a3aa0 g    DF .text 0000000000000597  Base        dns_ncache_getsigrdataset
/lib/x86_64-linux-gnu/libdns.so.110

然后再用 bpftrace,参考前面的 uprobe 例子。

7 /proc/<pid>/*

最后整理一些 /proc/<pid>/ 下面的信息。

7.1 /proc/<pid>/status

$ sudo cat /proc/200/status
Name:   ksoftirqd/37
Umask:  0000
State:  S (sleeping)
...
Cpus_allowed:   0020,00000000
Cpus_allowed_list:      37
voluntary_ctxt_switches:        27251
nonvoluntary_ctxt_switches:     350

其中,根据 NSpid 字段可以判断这个进程是不是容器

$ cat /proc/1229/status | grep NSpid
NSpid: 1229
$ cat /proc/11459/status | grep NSpid
NSpid: 11459 1 # 11459 是在宿主机的 pid ns 内的进程 ID,1 是在容器自己的 pid ns 的进程 ID

7.2 /proc/<pid>/stack

$ sudo cat /proc/20/stack
[<0>] smpboot_thread_fn+0x117/0x170
[<0>] kthread+0x12b/0x150
[<0>] ret_from_fork+0x22/0x30

7.3 /proc/<pid>/maps

$ docker ps
CONTAINER ID    IMAGE        COMMAND
b50745618ca2    3e6e2c29dbda  "./my-prog ..."   4 days ago   Up 4 days      k8s_my_test_prog

$ docker top b50745618ca2
UID                 PID                 PPID                C                   STIME               TTY                 TIME                CMD
root                10390               10363               0                   Jul08               ?                   00:15:19            ./my-prog ...

$ cat /proc/10390/status
Name:   mybin
Umask:  0022
State:  S (sleeping)
...
NStgid: 10390   1
NSpid:  10390   1
NSpgid: 10390   1
NSsid:  10390   1
Threads:        5
Cpus_allowed:   ffff,ffffffff
Cpus_allowed_list:      0-47
Mems_allowed_list:      0-1
voluntary_ctxt_switches:        2849002
nonvoluntary_ctxt_switches:     3008
$ cat /proc/10390/maps
00400000-008d2000 r-xp 00000000 fd:02 3233562123                         /my-prog
...
7fa61c6b3000-7fa61c732000 ---p 00000000 00:00 0
7fa61c732000-7fa61c792000 rw-p 00000000 00:00 0
7ffe97008000-7ffe97029000 rw-p 00000000 00:00 0                          [stack]
7ffe97102000-7ffe97106000 r--p 00000000 00:00 0                          [vvar]
7ffe97106000-7ffe97108000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 --xp 00000000 00:00 0                  [vsyscall]

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK