1
2
3
4
5
6
7
作者:李晓辉

联系方式:

1. 微信:Lxh_Chat

2. 邮箱:939958092@qq.com

上一篇我们学习了 perf。perf 依靠硬件性能计数器和软件性能事件,可以帮助我们找到程序的 CPU 时间主要消耗在哪里、哪些函数比较“忙”。 但是,perf 也有自己的关注范围。

比如现在有一个程序突然卡住了:

  • 为什么程序卡住不动?
  • 为什么一直打开、关闭文件?
  • 为什么频繁建立网络连接?
  • 为什么大量进行 read()、write()?
  • 为什么文件明明存在,程序却提示 No such file or directory?
  • 为什么某个系统调用一直返回 EAGAIN?

这时候,单纯依靠 perf 就不太够了。我们需要换一个角度,看看程序到底在和 Linux 内核做什么交互。这时候就要用到两个经典工具:

strace 和 ltrace。

可以先记住一句话:

perf 看“哪里最耗资源”,strace 看“程序和内核做了什么”,ltrace 看“程序调用了哪些用户态库函数”。


先搞清楚:系统调用和库函数到底是什么?

在 Linux 中,一个程序运行的时候,可以粗略理解成存在两个主要世界:

  • 用户空间(User Space)
  • 内核空间(Kernel Space)

我们平时运行的应用程序,例如:

1
2
3
4
5
6
Nginx
MySQL
Java
Python
Shell
业务程序

绝大多数代码都运行在用户空间。但是应用程序并不能随意访问所有系统资源。

比如:

  • 打开文件
  • 读取文件
  • 创建进程
  • 建立网络连接
  • 发送网络数据
  • 访问设备
  • 修改某些内核状态

这些资源由 Linux 内核统一管理。所以应用程序需要通过**系统调用(System Call)**向内核提出请求。可以先简单理解成:

flowchart TB
    A["应用程序<br/>Application"] --> B["用户空间<br/>User Space"]

    B --> C["库函数<br/>fopen / malloc / printf"]

    C --> D["系统调用<br/>openat / read / write / connect"]

    D --> E["系统调用入口"]

    E --> F["内核空间<br/>Kernel Space"]

    F --> G["文件系统"]
    F --> H["网络协议栈"]
    F --> I["进程管理"]
    F --> J["设备驱动"]

    C -. "ltrace 观察" .-> L["ltrace"]

    D -. "strace 观察" .-> S["strace"]

这张图里最关键的是:

库函数和系统调用不是一个东西。


库函数和系统调用有什么区别?

我们平时写程序的时候,经常直接使用一些库函数。例如 C 程序:

1
fopen("/etc/passwd", "r");

这里的:

1
fopen()

是一个库函数。它通常由 glibc 等用户态库提供。而 Linux 内核真正提供给用户程序的接口,则是系统调用,例如:

1
2
3
4
5
openat()
read()
write()
close()
connect()

因此,可以粗略理解为:

1
2
3
4
5
6
7
8
9
fopen()
│
│ 用户态库函数
▼
openat()
│
│ 系统调用
▼
Linux 内核

但是这里一定要注意一个细节:

库函数和系统调用并不是固定的一对一关系。

一个库函数可能:

  • 完全在用户空间执行;
  • 调用一个系统调用;
  • 调用多个系统调用;
  • 先在用户空间完成一些处理,再进入内核。

因此:

ltrace 和 strace 观察的是不同层次。


用户时间和系统时间也不要混淆

在 Linux 性能分析中,我们经常会看到:

1
2
User Time
System Time

也就是:

  • 用户态 CPU 时间
  • 内核态 CPU 时间

User Time

主要指 CPU 在用户空间执行程序代码所消耗的时间。

例如:

1
2
3
4
5
6
7
业务代码
↓
循环计算
↓
字符串处理
↓
算法计算

这些主要属于用户态执行。


System Time

主要指 CPU 在内核空间执行代码所消耗的时间。

例如:

1
2
3
4
5
6
7
8
9
10
应用程序
│
│ 系统调用
▼
Linux 内核
│
├── 文件系统
├── 网络协议栈
├── 进程管理
└── 设备驱动

这些内核代码运行期间产生的 CPU 时间,就属于系统态 CPU 时间。但这里有一个非常容易产生误解的地方:

系统时间并不等于“所有系统调用花费的时间”。

因为一个系统调用可能很快就返回,也可能在执行过程中阻塞等待。

例如:

1
2
3
4
5
read()
│
└── 等待数据
│
└── 进程睡眠

进程等待数据的时候,并不是 CPU 一直在执行这个进程的内核代码。

所以:

系统调用耗时、进程等待时间、CPU 在内核态实际执行的时间,并不是完全相同的概念。

这一点在后面的 strace 分析中非常重要。


strace:看看程序到底和内核做了什么

strace 是 Linux 中非常经典的系统调用跟踪工具。它可以跟踪进程执行的系统调用,并显示:

  • 系统调用名称
  • 传入参数
  • 返回值
  • 错误码
  • 调用耗时等信息

它特别适合排查:

1
2
3
4
5
6
7
8
文件打不开
权限错误
网络连接异常
程序阻塞
IO 行为异常
系统调用频繁
程序启动失败
系统调用返回错误

如果系统没有安装,可以:

1
[root@localhost ~]# dnf install strace -y

安装完成之后,就可以开始使用了。


案例 1:直接跟踪一条命令

最简单的使用方式,就是直接把要执行的命令交给 strace。

例如:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
[root@localhost ~]# strace uname
execve("/usr/bin/uname", ["uname"], 0x7ffd8a518ad0 /* 30 vars */) = 0
brk(NULL) = 0x5614eb10e000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f639f349000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=20095, ...}) = 0
mmap(NULL, 20095, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f639f344000
close(3) = 0
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\247\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
fstat(3, {st_mode=S_IFREG|0755, st_size=2339896, ...}) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 1936400, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f639f16b000
mmap(0x7f639f193000, 1376256, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7f639f193000
mmap(0x7f639f2e3000, 339968, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x178000) = 0x7f639f2e3000
mmap(0x7f639f336000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ca000) = 0x7f639f336000
mmap(0x7f639f33c000, 31760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f639f33c000
close(3) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f639f168000
arch_prctl(ARCH_SET_FS, 0x7f639f168740) = 0
set_tid_address(0x7f639f168a10) = 9899
set_robust_list(0x7f639f168a20, 24) = 0
rseq(0x7f639f169060, 0x20, 0, 0x53053053) = 0
mprotect(0x7f639f336000, 16384, PROT_READ) = 0
mprotect(0x5614cc8aa000, 4096, PROT_READ) = 0
mprotect(0x7f639f385000, 8192, PROT_READ) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
munmap(0x7f639f344000, 20095) = 0
getrandom("\xf7\x24\x22\x09\x26\xae\x43\x20", 8, GRND_NONBLOCK) = 8
brk(NULL) = 0x5614eb10e000
brk(0x5614eb12f000) = 0x5614eb12f000
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=229754784, ...}) = 0
mmap(NULL, 229754784, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6391600000
close(3) = 0
uname({sysname="Linux", nodename="localhost.localdomain", ...}) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(1, "Linux\n", 6Linux
) = 6
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++
[root@localhost ~]#

第一次看到这种输出,可能会觉得:

“这都是什么东西?”

别急,我们挑一行来看。

1
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

可以拆成:

1
2
3
4
5
6
7
8
9
10
11
系统调用:
openat()

参数:
AT_FDCWD
/etc/ld.so.cache
O_RDONLY
O_CLOEXEC

返回值:
3

返回值 3 表示:

文件打开成功,并返回文件描述符 3。

再看这一行:

1
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)

这里:

1
-1

表示系统调用失败。

而:

1
ENOENT

表示:

1
No such file or directory

也就是:

文件或目录不存在。

这就是 strace 非常有价值的地方。

我们不需要猜:

“是不是权限问题?”

直接看系统调用返回值,就可以知道内核到底返回了什么。


strace 的输出到底怎么看?

一条典型的 strace 输出:

1
2
3
4
5
openat(
AT_FDCWD,
"/etc/passwd",
O_RDONLY|O_CLOEXEC
) = 3

可以简单理解成:

1
2
3
4
5
6
7
8
9
10
11
            openat()
│
┌────────┴────────┐
│ │
输入参数 返回结果
│ │
/etc/passwd 3
│ │
└────────┬────────┘
│
成功

如果失败:

1
openat(AT_FDCWD, "/xxx", O_RDONLY) = -1 ENOENT

就是:

1
2
3
4
5
6
7
8
9
10
11
12
13
调用 openat()
│
▼
内核处理
│
▼
文件不存在
│
▼
返回 -1
│
▼
ENOENT

因此,排查程序异常时,strace 最大的优势之一就是:

你可以直接看到程序向内核提出了什么请求,以及内核返回了什么结果。


案例 2:-e 过滤系统调用

真实程序的系统调用可能非常多。如果全部打印出来:

1
strace some-program

很快就会刷屏。

这时候可以使用:

1
-e

过滤系统调用。

例如,我们只想观察文件打开:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
[root@localhost ~]# strace -e openat cat /etc/passwd
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/etc/passwd", O_RDONLY) = 3
root:x:0:0:Super User:/root:/bin/bash
bin:x:1:1:bin:/bin:/usr/sbin/nologin
daemon:x:2:2:daemon:/sbin:/usr/sbin/nologin
adm:x:3:4:adm:/var/adm:/usr/sbin/nologin
lp:x:4:7:lp:/var/spool/lpd:/usr/sbin/nologin
sync:x:5:0:sync:/sbin:/bin/sync
shutdown:x:6:0:shutdown:/sbin:/sbin/shutdown
halt:x:7:0:halt:/sbin:/sbin/halt
mail:x:8:12:mail:/var/spool/mail:/usr/sbin/nologin
operator:x:11:0:operator:/root:/usr/sbin/nologin
games:x:12:100:games:/usr/games:/usr/sbin/nologin
ftp:x:14:50:FTP User:/var/ftp:/usr/sbin/nologin
nobody:x:65534:65534:Kernel Overflow User:/:/usr/sbin/nologin
tss:x:59:59:Account used for TPM access:/:/usr/sbin/nologin
systemd-oom:x:999:999:systemd Userspace OOM Killer:/:/sbin/nologin
dbus:x:81:81:System Message Bus:/:/usr/sbin/nologin
sssd:x:998:998:User for sssd:/run/sssd/:/sbin/nologin
sshd:x:74:74:Privilege-separated SSH:/usr/share/empty.sshd:/usr/sbin/nologin
chrony:x:997:997:chrony system user:/var/lib/chrony:/sbin/nologin
systemd-coredump:x:996:996:systemd Core Dumper:/:/usr/sbin/nologin
pcp:x:995:995:Performance Co-Pilot:/var/lib/pcp:/usr/sbin/nologin
grafana:x:994:994:Grafana user account:/var/lib/grafana:/usr/sbin/nologin
polkitd:x:114:114:User for polkitd:/:/sbin/nologin
setroubleshoot:x:993:993:SELinux troubleshoot server:/var/lib/setroubleshoot:/usr/sbin/nologin
apache:x:48:48:Apache:/usr/share/httpd:/sbin/nologin
+++ exited with 0 +++

这样就只关注:

1
openat()

相关调用。

如果需要同时观察多个系统调用,可以:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
[root@localhost ~]# strace -e trace=openat,read,write,close cat /etc/passwd
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
close(3) = 0
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\247\2\0\0\0\0\0"..., 832) = 832
close(3) = 0
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
close(3) = 0
openat(AT_FDCWD, "/etc/passwd", O_RDONLY) = 3
read(3, "root:x:0:0:Super User:/root:/bin"..., 262144) = 1357
write(1, "root:x:0:0:Super User:/root:/bin"..., 1357root:x:0:0:Super User:/root:/bin/bash
bin:x:1:1:bin:/bin:/usr/sbin/nologin
daemon:x:2:2:daemon:/sbin:/usr/sbin/nologin
adm:x:3:4:adm:/var/adm:/usr/sbin/nologin
lp:x:4:7:lp:/var/spool/lpd:/usr/sbin/nologin
sync:x:5:0:sync:/sbin:/bin/sync
shutdown:x:6:0:shutdown:/sbin:/sbin/shutdown
halt:x:7:0:halt:/sbin:/sbin/halt
mail:x:8:12:mail:/var/spool/mail:/usr/sbin/nologin
operator:x:11:0:operator:/root:/usr/sbin/nologin
games:x:12:100:games:/usr/games:/usr/sbin/nologin
ftp:x:14:50:FTP User:/var/ftp:/usr/sbin/nologin
nobody:x:65534:65534:Kernel Overflow User:/:/usr/sbin/nologin
tss:x:59:59:Account used for TPM access:/:/usr/sbin/nologin
systemd-oom:x:999:999:systemd Userspace OOM Killer:/:/sbin/nologin
dbus:x:81:81:System Message Bus:/:/usr/sbin/nologin
sssd:x:998:998:User for sssd:/run/sssd/:/sbin/nologin
sshd:x:74:74:Privilege-separated SSH:/usr/share/empty.sshd:/usr/sbin/nologin
chrony:x:997:997:chrony system user:/var/lib/chrony:/sbin/nologin
systemd-coredump:x:996:996:systemd Core Dumper:/:/usr/sbin/nologin
pcp:x:995:995:Performance Co-Pilot:/var/lib/pcp:/usr/sbin/nologin
grafana:x:994:994:Grafana user account:/var/lib/grafana:/usr/sbin/nologin
polkitd:x:114:114:User for polkitd:/:/sbin/nologin
setroubleshoot:x:993:993:SELinux troubleshoot server:/var/lib/setroubleshoot:/usr/sbin/nologin
apache:x:48:48:Apache:/usr/share/httpd:/sbin/nologin
) = 1357
read(3, "", 262144) = 0
close(3) = 0
close(1) = 0
close(2) = 0
+++ exited with 0 +++

例如:

1
2
3
4
5
6
7
8
9
10
11
怀疑文件问题
↓
openat / openat2 / read / write / close

怀疑网络问题
↓
connect / accept / sendto / recvfrom

怀疑进程创建
↓
clone / fork / vfork / execve

这时候就可以有针对性地过滤。


为什么生产环境特别需要过滤?

假设一个业务程序一分钟执行几十万次系统调用。你直接:

1
strace -p 3831

那么终端可能瞬间刷出几万行。真正有价值的信息反而被淹没了。所以实际排查时经常是:

1
2
3
4
5
6
7
先猜问题类型
↓
确定可能相关的系统调用
↓
-e 过滤
↓
观察关键行为

案例 3:-p 附加到正在运行的进程

前面的方式是:

1
2
3
4
5
strace
↓
启动程序
↓
跟踪程序

但是生产环境通常不是这样。

假设现在:

1
2
sshd.service
PID = 3831

程序已经运行了很久。

突然出现:

1
2
3
请求超时
程序卡住
线程不响应

你不可能为了排查问题直接把生产服务停掉重新启动。

这时候可以:

1
strace -p 3831

让 strace 附加到正在运行的进程。

例如看到:

1
read(5,

然后很长时间没有继续输出。

这说明:

这个线程当前正在 read() 系统调用中等待。

如果看到:

1
connect(...)

长时间没有返回,可以进一步关注网络连接。

如果看到:

1
futex(...)

则可能涉及线程同步、锁竞争、条件变量等待等情况。


但这里千万不要形成一个误区

看到:

1
read(...)

并不意味着:

“问题一定出在 read()。”

例如:

1
2
3
4
5
6
7
8
9
10
应用程序
│
▼
read()
│
▼
等待数据
│
▼
真正的问题可能是另一个进程没有产生数据

所以 strace 首先告诉我们的,是:

程序当前正在做什么、当前阻塞在哪里。

真正的根因,还需要结合:

  • 应用程序逻辑
  • 文件系统
  • 网络
  • 线程
  • 锁
  • 上下游服务

进一步判断。


退出 strace一般情况下可以:

1
Ctrl + C

结束 strace 的跟踪。

正常情况下,结束 strace 本身不会主动终止被跟踪的目标进程。

不过生产环境一定要注意:

⚠️ 不要在业务高峰期长时间对核心生产进程进行完整 strace。

因为系统调用跟踪会引入额外开销。尤其是高并发、系统调用非常频繁的程序,更需要谨慎。


案例 4:-c 统计系统调用

如果我们并不关心:

“每一次系统调用具体传了什么参数?”

而更关心:

“这个程序到底调用了哪些系统调用?”

“哪个调用最多?”

“哪个调用累计耗时比较高?”

“哪个系统调用错误最多?”

那么:

1
-c

就非常好用了。

例如:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
[root@localhost ~]# strace -c uname
Linux
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
29.70 0.000120 13 9 mmap
11.39 0.000046 15 3 mprotect
10.89 0.000044 8 5 close
10.15 0.000041 10 4 fstat
7.67 0.000031 10 3 brk
5.69 0.000023 7 3 openat
4.95 0.000020 20 1 write
4.46 0.000018 18 1 munmap
3.47 0.000014 7 2 pread64
2.97 0.000012 12 1 uname
2.97 0.000012 12 1 getrandom
2.72 0.000011 11 1 rseq
0.74 0.000003 3 1 arch_prctl
0.74 0.000003 3 1 set_tid_address
0.74 0.000003 3 1 set_robust_list
0.74 0.000003 3 1 prlimit64
0.00 0.000000 0 1 read
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 execve
------ ----------- ----------- --------- --------- ----------------
100.00 0.000404 9 41 1 total


% time该系统调用在 strace 统计到的系统调用时间中所占的比例。

注意:

它不是整个程序 CPU 使用率的百分比。


seconds该系统调用累计花费的时间。


usecs/call平均每次系统调用花费的微秒数。

这个字段很有用。

例如:

1
2
3
read
calls = 1000000
usecs/call = 2

说明:

单次调用并不算特别慢,但调用次数非常多。

而如果:

1
2
3
read
calls = 100
usecs/call = 50000

则说明:

调用次数不多,但单次调用可能等待很久。

所以排查系统调用性能时,不能只盯着 % time。

还应该结合:

1
2
3
calls
usecs/call
errors

一起看。


calls系统调用次数。

例如:

1
openat    300000

说明程序在统计期间执行了大量 openat()。这时候就可以进一步思考:

“为什么这个程序一直在打开文件?”


errors系统调用返回错误的次数。

例如:

1
openat    ...    errors=300000

那就非常值得进一步排查。


syscall系统调用名称。


为什么 strace -c 非常适合做“系统调用画像”?

例如某个业务程序统计结果:

1
2
3
4
5
openat     500000
close 500000
read 300000
write 200000
connect 80000

这时候你马上就可以得到一个大致画像:

flowchart LR
    A["业务程序"] --> B["系统调用画像"]

    B --> C["openat<br/>大量调用"]
    B --> D["close<br/>大量调用"]
    B --> E["read / write<br/>频繁 IO"]
    B --> F["connect<br/>频繁网络连接"]

    C --> G["重点检查文件打开行为"]
    E --> H["重点检查 IO 行为"]
    F --> I["重点检查连接复用 / 网络行为"]

这就是:

1
strace -c

的价值。它不是告诉你每一次发生了什么。而是先帮你建立:

程序系统调用行为的整体画像。


案例 5:-f 跟踪子进程和线程

很多程序并不是只有一个执行实体。

比如:

1
2
3
4
父进程
├── 子进程
├── 子进程
└── 子进程

或者:

1
2
3
4
5
Java
├── Thread
├── Thread
├── Thread
└── Thread

如果只跟踪最初的目标,可能看不到后续创建出来的执行实体。这时候可以使用:

1
-f

例如:

1
strace -f some-command

-f 会跟踪目标进程通过 fork()、vfork()、clone() 等机制创建的相关进程/线程执行流。

例如:

1
strace -fc some-command

这里:

1
-f

负责跟踪相关进程/线程;

1
-c

负责最终统计系统调用。

所以:

1
-fc

可以简单理解为:

跟踪相关进程/线程,同时最终进行统计汇总。


组合案例:只统计 openat

假设我们已经知道:

“我怀疑这个程序是不是大量打开文件。”

那么没必要观察所有系统调用。直接:

1
2
3
4
5
6
7
8
[root@localhost ~]# strace -e openat -c uname
Linux
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.000046 15 3 openat
------ ----------- ----------- --------- --------- ----------------
100.00 0.000046 15 3 total

相当于:

1
2
3
只关注 openat
+
最终统计汇总

这种组合方式在生产环境临时排查问题时非常实用。


ltrace:看看程序在用户空间调用了什么

前面我们学习了:

strace 看系统调用。

但是程序的大量代码其实都运行在用户空间。例如:

1
2
3
4
5
6
malloc();
printf();
strcmp();
memcpy();
fopen();
gethostname();

这些通常属于用户态库函数。这时候可以使用:

1
ltrace

ltrace 主要用于跟踪程序对动态库函数的调用。

如果系统没有安装:

1
2
[root@localhost ~]# dnf install ltrace -y

安装完成后,可以直接:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
[root@localhost ~]# ltrace hostname
rindex("hostname", '/') = nil
strcmp("hostname", "dnsdomainname") = 4
strcmp("hostname", "domainname") = 4
strcmp("hostname", "ypdomainname") = -17
strcmp("hostname", "nisdomainname") = -6
getopt_long(1, 0x7ffd18a60f08, "aAdfbF:h?iIsVy", 0x559a980eea60, nil) = -1
__errno_location() = 0x7f31de3866e0
malloc(128) = 0x559ac34602a0
gethostname("localhost.localdomain", 128) = 0
memchr("localhost.localdomain", '\0', 128) = 0x559ac34602b5
puts("localhost.localdomain"localhost.localdomain
) = 22
__cxa_finalize(0x559a980eea40, 4, 0, 0x7ffd18a60c40) = 1
+++ exited (status 0) +++

这时候我们看到的不是:

1
2
3
4
openat()
mmap()
read()
close()

而是:

1
2
3
4
malloc()
strcmp()
gethostname()
puts()

这种用户态库函数调用。


ltrace ltrace 和 strace 到底有什么区别?

可以把它们放到一张图里:

flowchart TB
    A["应用程序"]

    A --> B["用户空间"]

    B --> C["库函数<br/>malloc / strcmp / fopen / printf"]
    C --> D["系统调用<br/>openat / read / write / connect"]

    D --> E["Linux 内核"]

    C -. "ltrace" .-> L["观察用户态库函数"]
    D -. "strace" .-> S["观察系统调用"]

    E --> F["文件系统"]
    E --> G["网络协议栈"]
    E --> H["进程管理"]

因此:

ltrace 更靠近应用程序。

strace 更靠近 Linux 内核。


ltrace ltrace 的 -S:库函数和系统调用一起看

ltrace 还有一个比较有意思的参数:

1
-S

例如:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
[root@localhost ~]# ltrace -S hostname
brk@SYS(nil) = 0x55fc8fc15000
mmap@SYS(nil, 8192, 3, 34, -1, 0) = 0x7f4509ddd000
access@SYS("/etc/ld.so.preload", 04) = -2
openat@SYS(AT_FDCWD, "/etc/ld.so.cache", 0x80000, 00) = 3
fstat@SYS(3, 0x7ffc029c2490) = 0
mmap@SYS(nil, 20095, 1, 2, 3, 0) = 0x7f4509dd8000
close@SYS(3) = 0
openat@SYS(AT_FDCWD, "/lib64/libc.so.6", 0x80000, 00) = 3
read@SYS(3, "\177ELF\002\001\001\003", 832) = 832
pread@SYS(3, 0x7ffc029c2200, 784, 64) = 784
fstat@SYS(3, 0x7ffc029c2490) = 0
pread@SYS(3, 0x7ffc029c20e0, 784, 64) = 784
mmap@SYS(nil, 1936400, 1, 2050, 3, 0) = 0x7f4509bff000
mmap@SYS(0x7f4509c27000, 1376256, 5, 2066, 3, 163840) = 0x7f4509c27000
mmap@SYS(0x7f4509d77000, 339968, 1, 2066, 3, 1540096) = 0x7f4509d77000
mmap@SYS(0x7f4509dca000, 24576, 3, 2066, 3, 1875968) = 0x7f4509dca000
mmap@SYS(0x7f4509dd0000, 31760, 3, 50, -1, 0) = 0x7f4509dd0000
close@SYS(3) = 0
mmap@SYS(nil, 12288, 3, 34, -1, 0) = 0x7f4509bfc000
arch_prctl@SYS(4098, 0x7f4509bfc740, 0, 34) = 0
set_tid_address@SYS(0x7f4509bfca10, 0x7f4509bfc740, 0x7f4509e1c0c8, 34) = 0x27f6
set_robust_list@SYS(0x7f4509bfca20, 24, 0x7f4509e1c0c8, 34) = 0
SYS_334@SYS(0x7f4509bfd060, 32, 0, 0x53053053) = 0
mprotect@SYS(0x7f4509dca000, 16384, 1) = 0
mprotect@SYS(0x55fc781e4000, 4096, 1) = 0
mprotect@SYS(0x7f4509e19000, 8192, 1) = 0
prlimit64@SYS(0, 3, 0, 0x7ffc029c2ff0) = 0
munmap@SYS(0x7f4509dd8000, 20095) = 0
rindex("hostname", '/') = nil
strcmp("hostname", "dnsdomainname") = 4
strcmp("hostname", "domainname") = 4
strcmp("hostname", "ypdomainname") = -17
strcmp("hostname", "nisdomainname") = -6
getopt_long(1, 0x7ffc029c33b8, "aAdfbF:h?iIsVy", 0x55fc781e4a60, nil) = -1
__errno_location() = 0x7f4509bfc6e0
malloc(128 <unfinished ...>
SYS_318@SYS(0x7f4509dd51f8, 8, 1, 0x7ffc029c2ff0) = 8
brk@SYS(nil) = 0x55fc8fc15000
brk@SYS(0x55fc8fc36000) = 0x55fc8fc36000
<... malloc resumed> ) = 0x55fc8fc152a0
gethostname( <unfinished ...>
uname@SYS(0x7ffc029c2b50) = 0
<... gethostname resumed> "localhost.localdomain", 128) = 0
memchr("localhost.localdomain", '\0', 128) = 0x55fc8fc152b5
puts("localhost.localdomain" <unfinished ...>
fstat@SYS(1, 0x7ffc029c3040) = 0
write@SYS(1, "localhost.localdomain\n", 22localhost.localdomain
) = 22
<... puts resumed> ) = 22
__cxa_finalize(0x55fc781e4a40, 4, 0, 0x7ffc029c30f0) = 1
exit_group@SYS(0 <no return ...>
+++ exited (status 0) +++
[root@localhost ~]#

这样可以让 ltrace 在跟踪库函数的同时,也显示系统调用。于是就可以观察类似:

1
2
3
4
5
6
7
8
9
10
11
用户程序
│
▼
库函数
gethostname()
│
▼
系统调用
│
▼
Linux 内核

这对于理解:

一个用户态库函数最终如何与内核产生联系

非常有帮助。不过需要注意:

ltrace 在不同程序、不同编译方式、不同库环境下,能够展示的信息可能不同。

例如:

  • 符号信息不足;
  • 静态链接;
  • 自研库;
  • 优化后的二进制;
  • 特殊运行时环境;

都可能影响跟踪效果。所以实际生产环境中:

strace 的使用频率通常明显高于 ltrace。


perf、strace、ltrace 到底怎么选?

现在我们已经有三个工具:

flowchart LR
    A["Linux 应用程序"]

    A --> P["perf"]
    A --> S["strace"]
    A --> L["ltrace"]

    P --> P1["性能事件<br/>CPU / Cache / Branch"]
    P1 --> P2["热点函数"]
    P2 --> P3["回答:<br/>哪里最耗资源?"]

    S --> S1["系统调用<br/>openat / read / write / connect"]
    S1 --> S2["参数 / 返回值 / 错误码"]
    S2 --> S3["回答:<br/>程序和内核做了什么?"]

    L --> L1["用户态库函数<br/>malloc / strcmp / fopen"]
    L1 --> L2["动态库调用"]
    L2 --> L3["回答:<br/>用户空间调用了什么?"]

可以记住一个非常简单的口诀:

CPU 高、想找热点函数 → perf

程序卡住、文件/网络/IO/权限异常 → strace

想观察用户态库函数调用 → ltrace


生产环境到底应该怎么排查?

实际生产环境中,不建议看到问题以后直接:

1
strace -p PID

然后让终端刷几万行。更合理的方式是:

flowchart TD
    A["发现程序异常"] --> B{"什么问题?"}

    B -->|"CPU 使用率高"| C["top"]
    C --> D["定位高 CPU 进程"]
    D --> E["perf stat"]
    E --> F["perf record"]
    F --> G["perf report"]
    G --> H["定位热点函数"]

    B -->|"程序卡住 / 阻塞"| I["strace -p PID"]
    I --> J{"当前在哪里?"}

    J -->|"文件 / IO"| K["read / write / openat"]
    J -->|"网络"| L["connect / recvfrom / sendto"]
    J -->|"线程同步"| M["futex 等"]

    B -->|"系统调用异常"| N["strace -c"]
    N --> O["统计调用次数 / 时间 / 错误"]
    O --> P["-e 精确过滤"]

    B -->|"怀疑用户态库函数"| Q["ltrace"]
    Q --> R["观察库函数调用"]

第一步:先确定问题类型

例如:

1
top

先确认:

1
2
3
CPU 高?
IO 异常?
程序卡住?

第二步:CPU 高 → perf

如果:

1
CPU 使用率很高

优先:

1
2
3
perf stat
perf record
perf report

回答:

CPU 到底消耗在哪段代码?


第三步:程序卡住 → strace

如果程序:

1
2
3
卡住
超时
没有响应

可以:

1
strace -p PID

观察:

当前正在执行或者等待哪个系统调用。


第四步:系统调用行为异常 → strace -c

如果怀疑:

1
2
3
4
系统调用太频繁
系统调用错误太多
文件打开次数异常
网络调用异常

可以:

1
strace -c -p PID

先建立整体画像。

然后再:

1
strace -e trace=openat,read,write,close -p PID

进一步缩小范围。


第五步:怀疑用户态库 → ltrace

如果问题明显发生在:

1
2
3
用户空间
动态库
glibc

可以考虑:

1
ltrace -p PID

进一步观察库函数调用。


几个生产环境特别值得注意的点

1. 优先使用统计模式

如果只是想了解系统调用分布:

1
strace -c

通常比完整打印所有调用更加合适。


2. 不要长时间跟踪核心生产进程

尤其是:

1
strace -p PID

系统调用跟踪会给目标进程增加额外开销。

所以生产环境更推荐:

1
2
3
短时间
小范围
有针对性

而不是:

1
2
3
长时间
全量系统调用
持续跟踪

3. 先过滤,再观察

不要一上来:

1
strace -p PID

让终端刷屏。

先思考:

1
2
3
4
5
6
7
8
9
10
11
怀疑文件?
↓
openat / read / write / close

怀疑网络?
↓
connect / accept / sendto / recvfrom

怀疑进程创建?
↓
clone / fork / vfork / execve

然后:

1
-e trace=...

精准过滤。


4. 错误码往往是排查问题的突破口

例如:

1
2
3
4
5
ENOENT
EACCES
EAGAIN
ECONNREFUSED
ETIMEDOUT

这些信息往往非常有价值。因为 strace 能直接告诉你:

程序向内核请求了什么,以及内核最终返回了什么。


把 perf、strace、ltrace 串起来

到这里,我们已经学习了三个非常重要的 Linux 性能分析工具。可以把它们理解成三个不同的“摄像机”。

flowchart TB
    A["Linux 应用程序"]

    A --> P["perf"]
    A --> S["strace"]
    A --> L["ltrace"]

    P --> P1["性能事件"]
    P1 --> P2["CPU / Cache / Branch"]
    P2 --> P3["热点函数"]
    P3 --> P4["哪里最耗资源?"]

    S --> S1["系统调用"]
    S1 --> S2["参数 / 返回值 / 错误码"]
    S2 --> S3["文件 / 网络 / IO / 进程"]
    S3 --> S4["程序和内核做了什么?"]

    L --> L1["用户态库函数"]
    L1 --> L2["glibc / 动态库"]
    L2 --> L3["用户空间调用路径"]
    L3 --> L4["程序调用了什么?"]

三个工具关注的层次不同。

  1. perf关注:性能

回答:

CPU 到底忙在哪里?


  1. strace关注:系统调用

回答:

程序和 Linux 内核做了什么?

  1. ltrace关注:用户态库函数

回答:

程序在用户空间调用了哪些库函数?


完整的 Linux 性能排查思路

如果把前面的知识全部串起来,我们就可以形成这样一套思路:

flowchart TD
    A["发现 Linux 性能 / 程序异常"] --> B["top / uptime / vmstat 等"]
    
    B --> C{"主要问题是什么?"}

    C -->|"CPU 高"| D["perf"]
    D --> D1["perf stat"]
    D1 --> D2["perf record"]
    D2 --> D3["perf report"]
    D3 --> D4["热点函数"]

    C -->|"程序卡住"| E["strace -p PID"]
    E --> E1["观察当前系统调用"]
    E1 --> E2["read / write / connect / futex ..."]

    C -->|"系统调用异常"| F["strace -c"]
    F --> F1["调用次数"]
    F --> F2["调用耗时"]
    F --> F3["错误数量"]

    C -->|"文件问题"| G["strace -e trace=openat,read,write,close"]
    C -->|"网络问题"| H["strace -e trace=connect,accept,sendto,recvfrom"]
    C -->|"用户态库问题"| I["ltrace"]

    D4 --> J["进一步定位代码 / 优化"]
    E2 --> J
    F1 --> J
    F2 --> J
    F3 --> J
    G --> J
    H --> J
    I --> J

这时候就可以发现:

Linux 性能分析并不是“记几个命令”。

真正重要的是:

看到问题以后,知道下一步应该观察什么。

系列小结

到这里,我们就把这一组 Linux 性能分析工具串起来了。前面我们学习了:

1
2
3
4
5
6
7
8
9
硬件性能
↓
sysctl
↓
TuneD
↓
cgroup
↓
资源限制

上一篇又学习了:

1
2
3
4
5
6
7
perf
↓
性能事件
↓
热点函数
↓
CPU 性能分析

这一篇进一步学习:

1
2
3
4
5
6
7
8
9
10
11
strace
↓
系统调用
↓
程序与内核的交互

ltrace
↓
库函数
↓
用户空间调用

最终,我们可以形成这样一个比较完整的思维模型:

flowchart LR
    A["Linux 性能问题"]

    A --> B["资源层"]
    A --> C["性能层"]
    A --> D["系统调用层"]
    A --> E["用户态库层"]

    B --> B1["sysctl / TuneD / cgroup"]

    C --> C1["perf"]
    C1 --> C2["热点函数"]

    D --> D1["strace"]
    D1 --> D2["系统调用 / 错误码 / 阻塞"]

    E --> E1["ltrace"]
    E1 --> E2["库函数调用"]

如果说:

top 告诉我们“谁有问题”;

那么:

perf 告诉我们“CPU 忙在哪里”;

strace 告诉我们“程序和内核做了什么”;

ltrace 告诉我们“程序在用户空间调用了什么”。

把这几个工具结合起来,我们就不再只是看到:

1
CPU 400%

或者:

1
程序卡住了

而是可以进一步追问:

1
2
3
4
5
6
7
8
9
10
11
12
13
谁有问题?
↓
CPU 在忙什么?
↓
程序正在执行什么?
↓
程序调用了什么系统调用?
↓
系统调用返回了什么?
↓
用户态又调用了哪些库函数?
↓
最终定位到真正的问题

这才是 Linux 性能分析真正有价值的地方。