Linux strace命令的用法

董哲

2023-12-01

前言：

Linux的strace命令简直就是一个调试神器。但是对于笔者而言却很陌生，一方面确实在实际生产中没有用到过这个命令，另一方面对操作系统方法不够熟悉，即使打印出了相关结果，也无法进行有效分析。

本文笔者是先学习了别人的关于strace命令的文章后，再来总结。

1.strace简介

在Linux系统中，strace命令是一个集诊断、调试、统计为一体的工具。

strace常用来跟踪进程执行时的系统调用和所接收的信号。

比如当进程进行磁盘读写时，会由用户态切换到内核态，而此时通过strace命令就可以跟踪到该进程所产生的的所有系统调用，包括参数、返回值、执行消耗时间等。

2.strace命令安装与参数释义

strace命令安装比较简单，笔者使用的是Ubuntu（docker）系统，安装命令如下：

apt-get install strace

而关于strace命令的使用，我们通过strace -h 来获取

root@7bc18553126f:/# strace -h    
usage: strace [-CdffhiqrtttTvVwxxy] [-I n] [-e expr]...
              [-a column] [-o file] [-s strsize] [-P path]...
              -p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]
   or: strace -c[dfw] [-I n] [-e expr]... [-O overhead] [-S sortby]
              -p pid... / [-D] [-E var=val]... [-u username] PROG [ARGS]

具体含义读者可以通过man strace来获取，笔者这里只列举一些重要的参数（来自 Linux strace命令 - ggjucheng - 博客园）

-c 统计每一系统调用的所执行的时间,次数和出错的次数等. 
-d 输出strace关于标准错误的调试信息. 
-f 跟踪由fork调用所产生的子进程. 
-ff 如果提供-o filename,则所有进程的跟踪结果输出到相应的filename.pid中,pid是各进程的进程号. 
-F 尝试跟踪vfork调用.在-f时,vfork不被跟踪. 
-h 输出简要的帮助信息. 
-i 输出系统调用的入口指针. 
-q 禁止输出关于脱离的消息. 
-r 打印出相对时间关于,,每一个系统调用. 
-t 在输出中的每一行前加上时间信息. 
-tt 在输出中的每一行前加上时间信息,微秒级. 
-ttt 微秒级输出,以秒了表示时间. 
-T 显示每一调用所耗的时间. 
-v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出. 
-V 输出strace的版本信息. 
-x 以十六进制形式输出非标准字符串 
-xx 所有字符串以十六进制形式输出. 
-a column 
设置返回值的输出位置.默认 为40. 

-e expr 
指定一个表达式,用来控制如何跟踪.格式如下: 
[qualifier=][!]value1[,value2]... 
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用来限定的符号或数字.默认的 qualifier是 trace.感叹号是否定符号.例如: 
-eopen等价于 -e trace=open,表示只跟踪open调用.而-etrace!=open表示跟踪除了open以外的其他调用.有两个特殊的符号 all 和 none. 
注意有些shell使用!来执行历史记录里的命令,所以要使用\\. 
-e trace=set 
只跟踪指定的系统 调用.例如:-e trace=open,close,rean,write表示只跟踪这四个系统调用.默认的为set=all. 
-e trace=file 
只跟踪有关文件操作的系统调用. 
-e trace=process 
只跟踪有关进程控制的系统调用. 
-e trace=network 
跟踪与网络有关的所有系统调用. 
-e strace=signal 
跟踪所有与系统信号有关的 系统调用 
-e trace=ipc 
跟踪所有与进程通讯有关的系统调用 
-e abbrev=set 
设定 strace输出的系统调用的结果集.-v 等与 abbrev=none.默认为abbrev=all. 
-e raw=set 
将指 定的系统调用的参数以十六进制显示. 
-e signal=set 
指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号. 
-e read=set 
输出从指定文件中读出 的数据.例如: 
-e read=3,5 
-e write=set 
输出写入到指定文件中的数据. 

-o filename 
将strace的输出写入文件filename 
-p pid 
跟踪指定的进程pid. 
-s strsize 
指定输出的字符串的最大长度.默认为32.文件名一直全部输出. 
-u username 
以username 的UID和GID执行被跟踪的命令

3.strace实战

3.1 通过strace查看系统命令执行情况

strace可以查看Linux系统命令执行过程，我们来查看下ls命令的执行情况，如下所示：

root@7bc18553126f:/tmp# strace ls /tmp/
execve("/bin/ls", ["ls", "/tmp/"], 0xfffff4816ae8 /* 11 vars */) = 0
brk(NULL)                               = 0xaaaac0227000
faccessat(AT_FDCWD, "/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
faccessat(AT_FDCWD, "/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=27837, ...}) = 0
mmap(NULL, 27837, PROT_READ, MAP_PRIVATE, 3, 0) = 0xffffa75f3000
close(3)                                = 0
faccessat(AT_FDCWD, "/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\320c\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=134296, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffa75f1000
mmap(NULL, 207032, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xffffa759d000
mprotect(0xffffa75bd000, 61440, PROT_NONE) = 0
mmap(0xffffa75cc000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1f000) = 0xffffa75cc000
mmap(0xffffa75ce000, 6328, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xffffa75ce000
close(3)                                = 0
...
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffa75ef000
mprotect(0xffffa7593000, 16384, PROT_READ) = 0
mprotect(0xffffa73b7000, 4096, PROT_READ) = 0
mprotect(0xffffa73d0000, 4096, PROT_READ) = 0
mprotect(0xffffa7442000, 4096, PROT_READ) = 0
mprotect(0xffffa75cc000, 4096, PROT_READ) = 0
mprotect(0xaaaaacb1c000, 8192, PROT_READ) = 0
mprotect(0xffffa75fd000, 4096, PROT_READ) = 0
munmap(0xffffa75f3000, 27837)           = 0
set_tid_address(0xffffa75ef500)         = 1455
set_robust_list(0xffffa75ef510, 24)     = 0
...
newfstatat(AT_FDCWD, "/tmp/", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}, 0) = 0
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) = 0
getdents64(3, /* 4 entries */, 32768)   = 104
getdents64(3, /* 0 entries */, 32768)   = 0
close(3)                                = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
write(1, "file  filetest.txt\n", 19file  filetest.txt
)    = 19
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

上述就是ls命令查看文件夹的全部系统调用过程（当然，笔者看不太懂...）

3.2 strace -e查看特定系统调用结果

3.1中ls命令的执行过程非常复杂，如果我们只想查看特定系统系统调用的结果，可以使用strace -e命令，如下所示

# 只查看read命令执行
root@7bc18553126f:/tmp# strace -e read ls /tmp/
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\320c\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0`\10\2\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\360\27\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\320\16\0\0\0\0\0\0"..., 832) = 832
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\330\\\0\0\0\0\0\0"..., 832) = 832
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 436
read(3, "", 1024)                       = 0
file  filetest.txt
+++ exited with 0 +++

# 只查看openat命令执行
root@7bc18553126f:/tmp# strace -e openat ls /tmp/
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/lib/aarch64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
file  filetest.txt
+++ exited with 0 +++

这样，相对而言就比较清晰，我们也可以更聚焦特定操作结果。

3.3 strace -c 统计调用情况

在我们分析系统运行问题时，有时候需要对该命令或进程的执行情况进行统计，根据统计耗时来判断具体的性能问题点，这时就可以使用-c来获取结果

root@7bc18553126f:/tmp# strace -c ls /tmp/
file  filetest.txt
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 25.44    0.001067          67        16           mmap
 17.72    0.000743          62        12           mprotect
  9.44    0.000396          44         9           fstat
  8.44    0.000354          51         7           read
  8.01    0.000336          34        10           close
  6.70    0.000281          35         8           openat
  5.17    0.000217          27         8         8 faccessat
  2.77    0.000116          39         3           brk
  2.60    0.000109          55         2         2 statfs
  2.41    0.000101         101         1           rt_sigprocmask
  2.36    0.000099          99         1           prlimit64
  1.93    0.000081          41         2           getdents64
  1.62    0.000068          68         1           munmap
  1.50    0.000063          32         2           rt_sigaction
  1.12    0.000047          24         2           ioctl
  0.86    0.000036          36         1           set_robust_list
  0.83    0.000035          35         1           write
  0.69    0.000029          29         1           newfstatat
  0.38    0.000016          16         1           set_tid_address
  0.00    0.000000           0         1           execve
------ ----------- ----------- --------- --------- ----------------
100.00    0.004194                    89        10 total

根据统计结果来看，mmap占用时间最多，而该命令总耗时为0.004194秒

3.4 strace查看执行时间

3.3中通过-c来统计各个命令的执行占用时间比，如果我们想查看strace中每个系统命令执行耗时或执行的时间应该怎么做呢

我们可以通过-t -tt -T 来获取

# -t以秒级展示调用执行时间
root@7bc18553126f:/tmp# strace -t -e connect,poll,select,recvfrom,sendto nc curl 192.168.3.18:80
10:05:28 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
10:05:28 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
10:05:28 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, 16) = 0
10:05:28 sendto(3, "\337\362\1\0\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 22, MSG_NOSIGNAL, NULL, 0) = 22
10:05:28 recvfrom(3, "\337\362\201\203\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, [28->16]) = 22
curl: forward host lookup failed: Unknown host
10:05:28 +++ exited with 1 +++

# -tt 以微秒级展示调用执行事件
root@7bc18553126f:/tmp# strace -tt -e connect,poll,select,recvfrom,sendto nc curl 192.168.3.18:80
10:05:45.988119 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
10:05:45.989054 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
10:05:46.007491 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, 16) = 0
10:05:46.007885 sendto(3, "\343`\1\0\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 22, MSG_NOSIGNAL, NULL, 0) = 22
10:05:46.014104 recvfrom(3, "\343`\201\203\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, [28->16]) = 22
curl: forward host lookup failed: Unknown host
10:05:46.016733 +++ exited with 1 +++

# -T 展示每一步的系统耗时
root@7bc18553126f:/tmp# strace -T -e connect,poll,select,recvfrom,sendto nc  curl 192.168.3.18:80
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000241>
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000790>
connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, 16) = 0 <0.000152>
sendto(3, "\351\335\1\0\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 22, MSG_NOSIGNAL, NULL, 0) = 22 <0.000101>
recvfrom(3, "\351\335\201\203\0\1\0\0\0\0\0\0\4curl\0\0\1\0\1", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.5")}, [28->16]) = 22 <0.000241>
curl: forward host lookup failed: Unknown host
+++ exited with 1 +++

3.5 strace -o 将执行结果输出到特定文件

这个比较简单，也比较实用

root@7bc18553126f:/tmp# strace -T -o stracelog.txt -e connect,poll,select,recvfrom,sendto nc  curl 192.168.3.18:80
curl: forward host lookup failed: Unknown host

执行结果直接保存到当前目录下stracelog.txt文件中

3.6 strace -p 跟踪具体进程

这个应该是我们最实用的一个命令了，在产线中常常需要查看某个进程的具体执行信息。

笔者先启动一个docker nginx，端口为80

然后进入nginx后，安装strace命令，监控所有nginx进程

# 查看所有nginx进程
root@aa4e7f274852:/tmp# ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 10:31 ?        00:00:00 nginx: master process nginx -g daemon off;
nginx       35     1  0 10:31 ?        00:00:00 nginx: worker process
nginx       36     1  0 10:31 ?        00:00:00 nginx: worker process
nginx       37     1  0 10:31 ?        00:00:00 nginx: worker process
nginx       38     1  0 10:31 ?        00:00:00 nginx: worker process

# strace监控所有nginx进程
root@aa4e7f274852:/tmp# strace -o /tmp/log.txt -tt -p 1 -p 35 -p 36 -p 37 -p 38
strace: Process 1 attached
strace: Process 35 attached
strace: Process 36 attached
strace: Process 37 attached
strace: Process 38 attached

# 在外部访问nginx 80端口
curl localhost:80

# 查看/tmp/log.txt日志信息
root@aa4e7f274852:/tmp# more log.txt 
38    10:53:57.440787 epoll_pwait(16,  <unfinished ...>
37    10:53:57.441067 epoll_pwait(14,  <unfinished ...>
36    10:53:57.451890 epoll_pwait(12,  <unfinished ...>
1     10:53:57.451983 rt_sigsuspend([], 8 <unfinished ...>
35    10:53:57.452449 epoll_pwait(10,  <unfinished ...>
36    10:54:00.347724 <... epoll_pwait resumed>[{EPOLLIN, {u32=2858401808, u64=281473540145168}}], 512, -1, NULL, 8) = 1
36    10:54:00.347934 accept4(7, {sa_family=AF_INET, sin_port=htons(60990), sin_addr=inet_addr("172.17.0.1")}, [112->16], SOCK_NONBLOCK) = 15
36    10:54:00.348209 epoll_ctl(12, EPOLL_CTL_ADD, 15, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=2858402528, u64=281473540145888}}) = 0
36    10:54:00.348388 epoll_pwait(12, [{EPOLLIN, {u32=2858402528, u64=281473540145888}}], 512, 60000, NULL, 8) = 1
36    10:54:00.348552 recvfrom(15, "GET / HTTP/1.1\r\nHost: localhost\r"..., 1024, 0, NULL, NULL) = 73
36    10:54:00.348806 newfstatat(AT_FDCWD, "/usr/share/nginx/html/index.html", {st_mode=S_IFREG|0644, st_size=615, ...}, 0) = 0
36    10:54:00.348967 openat(AT_FDCWD, "/usr/share/nginx/html/index.html", O_RDONLY|O_NONBLOCK) = 16
36    10:54:00.349126 fstat(16, {st_mode=S_IFREG|0644, st_size=615, ...}) = 0
36    10:54:00.349296 writev(15, [{iov_base="HTTP/1.1 200 OK\r\nServer: nginx/1"..., iov_len=238}], 1) = 238
36    10:54:00.349556 sendfile(15, 16, [0] => [615], 615) = 615
36    10:54:00.350389 write(6, "172.17.0.1 - - [23/Apr/2022:10:5"..., 91) = 91
36    10:54:00.351039 close(16)         = 0
36    10:54:00.351257 setsockopt(15, SOL_TCP, TCP_NODELAY, [1], 4) = 0
36    10:54:00.351297 epoll_pwait(12, [{EPOLLIN|EPOLLRDHUP, {u32=2858402528, u64=281473540145888}}], 512, 65000, NULL, 8) = 1
36    10:54:00.351574 recvfrom(15, "", 1024, 0, NULL, NULL) = 0
36    10:54:00.351799 close(15)         = 0
36    10:54:00.352559 epoll_pwait(12,  <detached ...>

该日志就是本次访问所产生的系统调用日志