strace 哇,好多系统调用

2021-11-13  本文已影响0人  hanpfei

我不敢在没有认真考虑后果的情况下在生产环境中运行 strace(1),而是首先尝试它的替代品。尽管广为人知的是(并且不断被重新发现)strace 是一个神奇的工具,但少得多的人知道的是,它目前是 — 且一直以来都是 — 很危险的。

strace 是 Linux 的系统调用追踪器。它当前使用了神秘的 ptrace() (进程追踪)调试接口,后者以一种很暴力的方式运作:每次系统调用都暂停目标进程以使得调试器可以读取状态。且执行两次:系统调用开始时一次,结束时一次。

这意味着每次系统调用 strace 都暂停你的应用程序两次,且每次都在应用程序和 strace 之间切换上下文。这就像在你的应用程序中放了一个流量计量灯。

BUGS:被追踪的进程运行缓慢
– strace(1) man page

在某些情况下这不是问题。你的应用程序可能一开始就完全被破坏了,或者你可以在一个速度无所谓的测试环境中运行它。在生产中,你将想要真正地小心,并考虑后果(比如,这可能会导致目标因超出延时阈值而失败么?)。最好是先找其它的替代品试试,比如 Linux 的 perf_events

doge-strace

开销

strace 的性能开销与它所检测的系统调用的频率相关。为了给它设定一个上界,这里是一个简单的最差情况的测试:

$ dd if=/dev/zero of=/dev/null bs=1 count=500k
记录了512000+0 的读入
记录了512000+0 的写出
512000 bytes (512 kB, 500 KiB) copied, 0.429502 s, 1.2 MB/s

这在 0.429502 s 内执行完成。

现在通过 strace 来执行(这里我追踪一个从未被调用到的系统调用,accept(),但我们依然要为此付出开销):

$ strace -eaccept dd if=/dev/zero of=/dev/null bs=1 count=500k 
记录了512000+0 的读入
记录了512000+0 的写出
512000 bytes (512 kB, 500 KiB) copied, 82.7162 s, 6.2 kB/s
+++ exited with 0 +++

这次慢了 193 倍。这是最坏的情况,因为 dd(1) 正在尽可能快地执行系统调用。

方便的 strace 一行短命令

# 降低目标命令的速度并打印每个系统调用的详细信息:
strace command

# 降低目标 PID 的速度并打印每个系统调用的详细信息:
strace -p PID

# 降低目标 PID 及其任何新创建的子进程的速度,打印系统调用的详细信息:
strace -fp PID

# 降低目标 PID 的速度,记录系统调用,并打印一个总结:
strace -cp PID

#  降低目标 PID 的速度,并只打印 open() 系统调用:
strace -eopen -p PID

# 降低目标 PID 的速度,并只打印 open()  和 stat() 系统调用:
strace -eopen,stat -p PID

# 降低目标 PID 的速度,并只打印 connect()  和 accept() 系统调用:
strace -econnect,accept -p PID

# 降低目标命令的速度并查看它启动了哪些其它程序(也降低它们的速度):
strace -qfeexecve command

# 降低目标 PID 的速度并以(扭曲的)微秒分辨率打印纪元时间:
strace -ttt -p PID

# 降低目标 PID 的速度并以(扭曲的)微秒分辨率打印系统调用的持续时间:
strace -T -p PID

如何学习 strace

关于解释 strace 的输出,你有许多可以学的。下面两个步骤应该可以让你开始关键的系统调用。

1. 学习关键的系统调用

你应该了解如下 12 个关键的系统调用做了什么,你会经常在 strace 的输出中看到它们。测试你的知识!你知道这些系统调用中的多少呢?

系统调用 它做了什么
read 从一个文件描述符(文件,socket)读取字节
write 向一个文件描述符(文件,socket)写入字节
open 打开一个文件(返回一个文件描述符)
close 关闭一个文件描述符
fork 创建一个新进程(当前进程被分叉)
exec 执行一个新程序
connect 连接到一个网络主机
accept 接受一个网络连接
stat 读取文件统计信息
ioctl 设置 I/O 属性,或其它杂项函数
mmap 将一个文件映射到进程内存地址空间
brk 扩展堆指针

每个系统调用都有一个手册页,因此,如果你在命令行中,应该只需要几秒钟就可以唤醒你的记忆。

这些系统调用有一些变体,因此你可能看到的 "exec" 的变体 "execve",和 "read" 的变体 "pread"。这些应该也有手册页。

2. 简单的 strace 例子

你可以通过一些基本的命令来练习和学习strace:ls(1),sleep(1),ssh(1),等等。

让我们 strace 珍贵的 ls -l 作为我们的第一个例子。我们将列出 /etc 的内容,以便于有大量的文件需要检测,输出基本上是你所期望的(列出文件)而不是程序启动和初始化。

输出从显示程序初始化开始:

$ strace ls -l /etc/
execve("/bin/ls", ["ls", "/etc"], 0x7ffe22ee51b8 /* 59 vars */) = 0
brk(NULL)                               = 0x559965d4e000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/haswell/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "tls/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "haswell/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "x86_64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "libselinux.so.1", O_RDONLY|O_CLOEXEC) = -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=110853, ...}) = 0
mmap(NULL, 110853, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fdf9a94d000
close(3)                                = 0

execve() 变体用于运行 /bin/ls,然后是动态链接库被拉进来。有多组以 openat() 一个 /lib* 位置开始,以 close() 结束的输出。

以读取一行为例:看一眼 openat() 行,还有 openat(2) 的手册页。手册页总结了这个系统调用:

       #include <sys/types.h>
       #include <sys/stat.h>
       #include <fcntl.h>

       int open(const char *pathname, int flags);
       int open(const char *pathname, int flags, mode_t mode);

       int creat(const char *pathname, mode_t mode);

       int openat(int dirfd, const char *pathname, int flags);
       int openat(int dirfd, const char *pathname, int flags, mode_t mode);

它还详细地解释了这些参数,和返回值。因此,我们的 "pathname" /etc/ld.so.cache,而 flags 是 O_RDONLY|O_CLOEXEC。它返回 3,一个文件描述符以备后面用于其它系统调用。

在稍后的输出中,真正的操作开始了:

openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000b\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=144976, ...}) = 0
mmap(NULL, 2221184, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6de9063000
mprotect(0x7f6de907d000, 2093056, PROT_NONE) = 0
mmap(0x7f6de927c000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19000) = 0x7f6de927c000
mmap(0x7f6de927e000, 13440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6de927e000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6de9f18000
arch_prctl(ARCH_SET_FS, 0x7f6de9f19040) = 0
mprotect(0x7f6de9adf000, 16384, PROT_READ) = 0
mprotect(0x7f6de927c000, 4096, PROT_READ) = 0
mprotect(0x7f6de9484000, 4096, PROT_READ) = 0
mprotect(0x7f6de96f6000, 4096, PROT_READ) = 0
mprotect(0x7f6de9d0d000, 4096, PROT_READ) = 0
mprotect(0x561ff9332000, 8192, PROT_READ) = 0
mprotect(0x7f6de9f38000, 4096, PROT_READ) = 0
munmap(0x7f6de9f1c000, 110853)          = 0
set_tid_address(0x7f6de9f19310)         = 4539
set_robust_list(0x7f6de9f19320, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f6de9068cb0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f6de90758a0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f6de9068d50, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f6de90758a0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
statfs("/sys/fs/selinux", 0x7ffcc72c6280) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffcc72c6280)      = -1 ENOENT (No such file or directory)
brk(NULL)                               = 0x561ffac34000
brk(0x561ffac55000)                     = 0x561ffac55000
openat(AT_FDCWD, "/proc/filesystems", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(3, "nodev\tsysfs\nnodev\ttmpfs\nnodev\tbd"..., 1024) = 395
read(3, "", 1024)                       = 0
close(3)                                = 0
access("/etc/selinux/config", F_OK)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=4799968, ...}) = 0
mmap(NULL, 4799968, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6de8bcf000
close(3)                                = 0
ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(1, TIOCGWINSZ, {ws_row=42, ws_col=161, ws_xpixel=0, ws_ypixel=0}) = 0
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2995, ...}) = 0
read(3, "# Locale name alias data base.\n#"..., 4096) = 2995
read(3, "", 4096)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "/usr/share/locale/zh_CN/LC_TIME/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/zh/LC_TIME/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=26376, ...}) = 0
mmap(NULL, 26376, PROT_READ, MAP_SHARED, 3, 0) = 0x7f6de9f31000
close(3)                                = 0
futex(0x7f6de9ae4a08, FUTEX_WAKE_PRIVATE, 2147483647) = 0
lstat("/etc/", {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
lgetxattr("/etc/", "security.selinux", 0x561ffac35ec0, 255) = -1 ENODATA (No data available)
getxattr("/etc/", "system.posix_acl_access", NULL, 0) = -1 ENODATA (No data available)
getxattr("/etc/", "system.posix_acl_default", NULL, 0) = -1 ENODATA (No data available)
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=556, ...}) = 0
read(3, "# /etc/nsswitch.conf\n#\n# Example"..., 4096) = 556
read(3, "", 4096)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "tls/haswell/x86_64/libnss_compat.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
mprotect(0x7f57d149e000, 4096, PROT_READ) = 0
mprotect(0x7f57d16bc000, 4096, PROT_READ) = 0
mprotect(0x7f57d18ca000, 4096, PROT_READ) = 0
munmap(0x7f57d2e03000, 110853)          = 0
openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
lseek(3, 0, SEEK_CUR)                   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2525, ...}) = 0
mmap(NULL, 2525, PROT_READ, MAP_SHARED, 3, 0) = 0x7f57d2e37000
lseek(3, 2525, SEEK_SET)                = 2525
munmap(0x7f57d2e37000, 2525)            = 0
close(3)                                = 0
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 3
lseek(3, 0, SEEK_CUR)                   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=940, ...}) = 0
mmap(NULL, 940, PROT_READ, MAP_SHARED, 3, 0) = 0x7f57d2e37000
lseek(3, 940, SEEK_SET)                 = 940
munmap(0x7f57d2e37000, 940)             = 0
close(3)                                = 0
openat(AT_FDCWD, "/etc/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=12288, ...}) = 0
getdents(3, /* 244 entries */, 32768)   = 7904
[...]

这里打开 /etc 并读取目录项(getdents()),然后针对每一个文件调用 lstat(),一个 stat() 变体,即两个扩展属性变体:lgetxattr() 和 getxattr()。getxattr() 被调了两次,每一个命名空间一次:看它的第二个参数。

收集了所有这些文件信息之后,ls(1) 开始打印输出,有序的:

openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=582, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=582, ...}) = 0
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\3\0\0\0\3\0\0\0\0"..., 4096) = 582
lseek(3, -357, SEEK_CUR)                = 225
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\3\0\0\0\3\0\0\0\0"..., 4096) = 357
close(3)                                = 0
write(1, "\346\200\273\347\224\250\351\207\217 1432\ndrwxr-xr-x  3 roo"..., 4096总用量 1432
drwxr-xr-x  3 root root     4096 2月   4  2020 acpi
-rw-r--r--  1 root root     3028 2月   4  2020 adduser.conf
drwxr-xr-x  2 root root    12288 11月  8 18:24 alternatives
-rw-r--r--  1 root root      401 5月  30  2017 anacrontab
drwxr-xr-x  3 root root     4096 6月  28  2020 apache2
-rw-r--r--  1 root root      433 10月  2  2017 apg.conf
drwxr-xr-x  6 root root     4096 2月   4  2020 apm
drwxr-xr-x  3 root root     4096 2月   4  2020 apparmor
drwxr-xr-x  8 root root     4096 11月  5 06:38 apparmor.d
drwxr-xr-x  4 root root     4096 10月 29 11:23 apport
-rw-r--r--  1 root root      769 4月   4  2018 appstream.conf
[...]

输出有点混乱,这是由于 ls -lstrace 都写入相同的终端。ls 通过几次 write() 调用输出所有的文件信息。

性能调优 ls(1)

线上的快速搜索(我接下来会去找 ls(1) 的根源)解释了这里看到的问题:我的 TZ 环境变量没有设置。设置它以消除那些针对 /etc/localtime 的 stat() 调用。

通过这个简单的例子,我发现了一个性能上的优势。我当然是这个意思了。

引导 ls(1) 运行足够长的时间以进行性能测量:

$ time ls -l `perl -e 'print "/etc " x 1000'` >/dev/null

real    0m3.562s
user    0m1.004s
sys 0m2.464s

修复之后的结果:

$ time TZ=US/Pacific ls -l `perl -e 'print "/etc " x 1000'` >/dev/null

real    0m2.753s
user    0m0.804s
sys 0m1.868s

我只提升了性能 23% (2.753s 相比于 3.562s)。还不坏。(对于发现并消除 stat() 我没感到很兴奋,尽管,因为它们是快速的系统调用,且获得的回报通常不会这么高。)

这是一个很好的 strace 善于识别的性能问题的类型的例子:负载的问题。尽管我们是通过围绕 strace 钓鱼发现它的,这也能通过如下的性能方法论发现:负载特征分析,针对系统调用的。

由于它会严重扭曲时间测量值(尽管它没有 "-O overhead" 选项,并启发式地,去试图补偿),strace 不擅长决定包括延迟在内的性能问题。且在系统调用接口之外它也很少被用到,比如性能问题位于更深入的内核或应用程序中。

2018 年的 strace 版本中这个问题也早已经被修复了。

与先进跟踪器对比

对于当前版本的 strace(如,版本 4.8)和当前版本的 perf_events/ktap/SystemTap/LTTng/dtrace4linux (根据 2014 年)相比。

优势:

缺点:

有一个可能的缺点:在过去,strace 有 bug,可能会留目标进程,或它跟随的子进程,处于 STOP 状态(比如,这里这里)。这可能会导致严重的生产故障,由于应用程序现在在运行中被冻结了。如果你立即意识到并能够修复它(杀掉 strace,然后 kill -CONT 进程),则你可以避免一次严重的故障。然而,你可能依然会导致一次突发的应用程序请求有好几秒(异常值)的延时的情况,这依赖于你键入 kill 命令的速度有多快。

如果你想写一篇关于 strace 有多棒并展示它的用法的例子的博客,那很棒,但请复制上面警告的要点。

你知道么?

更多关于 strace

由于下面的文章似乎缺少对于开销的警告,我在链接上添加了一个确认框:

这些文章可能很有用,因为它们展示了真实问题的案例研究,并基于每个作者关心的领域和所擅长的应用 strace 的知识提供了不同的视角。

如果你想学习更多关于 strace 内部和 ptrace() 的内容,我建议:

这里列的一些文章,有许多链接已失效。

strace 之外

有许多关于 strace(1) 的文章和通讯,和 tcpdump(8) 及 top(1) 一样,但关于更难的 Linux 观测工具和框架的就少多了,比如 ltrace (库追踪),perf_events,tracepoints,kprobes,uprobes,等等。我在我的 SCaLE12x keynote 中调侃了这一点,展示了一副 简化的 仅由 top,strace,和 tcpdump 组成的 Linux 内部图!

strace 能见度有限:(可测量版本的)系统调用接口。我右边的 Linux 性能观察工具图显示了 strace 与其他工具的范围。现在,可以从系统调用请求推断出内核活动的很多信息,但是有很多领域你无法直接看到。浏览该图表,查看可以用于超越 strace 的其它工具。

linuxperftools-600.png

我常常跳过 strace,而直接使用这些其它工具,比如 perf(perf_events)或者其它正在开发中的 Linux 动态跟踪器。这些给了我更深的能见度,更低的开销,及可定制的输出。尽管,有时候最快的方法只是启动 strace,如果开销是可以接受的,我也会这么做。

strace 的未来

strace(1) 是一个伟大的工具,但当前的版本(使用 ptrace())可能严重地降低目标的速度。注意 strace 引起的开销,并考虑 Linux 的其它使用了开销更低的缓冲追踪机制的替代品。这些包括 perf_events,sysdig,ktap,和SystemTap。这些中的许多也允许定制内核摘要,以进一步减少开销。

Linux 3.7 引入了 perf trace,一个缓冲的类 strace 的 perf_events 子命令,它作为一个 "strace 替代品" 而被引入。还有 sysdig,它允许定制过滤器和输出。未来很有可能 strace 将变成这些工具的包装器,而我所有的关于开销的警告也将过时(不过,这并不意味着可以忽略开销!)。

【原文】strace Wow Much Syscall

上一篇下一篇

猜你喜欢

热点阅读