Linux tracing/profiling 基础:符号表、调用栈、perf/bpftrace 示例等(2022)
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.
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,就可以分析性能和调用栈。例如,
-
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 ...
这是一个交互式的窗口,可以选中具体函数展开查看详情。
-
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]) ...
-
将
perf script
的输出重定向到 perl 脚本做进一步处理,就得到了著名的火焰图:$ perf script | ./stackcollapse-perf.pl | ./flamegraph.pl > result.svg
这些都是基于 tracing 功能。
1.2 符号(symbols)
Tracing 功能的基础是符号(symbols),即目标文件中的函数信息。 Symbols 对 kprobe/uprobe event tracing 至关重要,因为知道函数名字才能跟踪。来看两个例子:
-
查看
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) ...
-
查看内核符号表:
$ 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]
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK