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

联系方式:

1. 微信:Lxh_Chat

2. 邮箱:939958092@qq.com
  1. Linux 性能调优系列(一) 建立科学的性能分析思路
  2. Linux 性能调优系列(二) 掌握基础性能监控命令
  3. Linux 性能调优系列(三) sysstat实现性能数据持久采集
  4. Linux 性能调优系列(四) 别只会用 sysstat,PCP 才是 Linux 性能监控的进阶玩法
  5. Linux 性能调优系列(五) 给你的服务器做一次全面体检
  6. Linux 性能调优系列(六) 想调内核参数?先搞懂 /proc、sysctl 和 sysfs
  7. Linux 性能调优系列(七) 还在手动改 sysctl?TuneD 智能性能调优实战来了
  8. Linux 性能调优系列(八) 进程太能吃资源怎么办?用 ulimit 和 systemd 给它加个"上限"
  9. Linux 性能调优系列(九) cgroup v2实战:防止一个烂进程干崩整台服务器
  10. Linux 性能调优系列(十) CPU 100% 到底是谁在忙?用 perf 把"元凶"揪出来
  11. Linux 性能调优系列(十一) 程序为什么卡住了?strace 和 ltrace 带你找到答案
  12. Linux 性能调优系列(十二) 服务器又卡了?SystemTap 带你杀到内核看看为啥
  13. Linux 性能调优系列(十三) 从 SystemTap 到 eBPF,Linux 性能追踪进入新时代
  14. Linux 性能调优系列(十四) CPU 这么忙,到底是谁决定“让谁先跑”?一文搞懂 Linux 调度器
  15. Linux 性能调优系列(十五) CPU 到底该先给谁?搞懂 Linux 实时调度
  16. Linux 性能调优系列(十六) Linux CPU 隔离实战,为什么实时线程绑核后延迟还会抖?
  17. Linux 性能调优系列(十七) CPU 占用不高却跑的慢?深挖 CPU 缓存性能瓶颈
  18. Linux 性能调优系列(十八) 程序申请了1GB内存,为什么系统却说它没用?
  19. Linux 性能调优系列(十九) 服务器硬盘慢得像蜗牛?先别急着换硬盘,这四招先把瓶颈找出来
  20. Linux 性能调优系列(二十) 磁盘 I/O 调度器怎么选?一文搞懂 mq-deadline、kyber、bfq 和 none
  21. Linux 性能调优系列(二十一) 磁盘为什么慢?从文件系统到 I/O 调优,一次讲透
  22. Linux 性能调优系列(二十二) Linux 网络调优别乱改 sysctl!先找瓶颈再调 TCP 缓冲区
  23. Linux 性能调优系列(二十三) MTU 从 1500 到 9000,巨帧真的能提升性能吗?
  24. Linux 性能调优系列(二十四) 从 CPU 省电到网卡卸载,聊聊 Linux 网络调优
  25. Linux 性能调优系列(二十五) 聊聊VirtIO、TuneD、virtio-mem 调优

上一篇我们学习了 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 性能分析真正有价值的地方。