使用Stace排除故障的5种简单方法

Posted 2022-06-22 -飞鹤-

我一直很惊讶很少有人意识到他们能够使用Strace做的所有事情。它一直是我最先推出的调试工具之一，因为它通常在我使用的Lunux系统上是可用的，并且它能够被用来解决如此广泛的问题。

strace是什么？

Strace是一个追踪可执行程序系统调用的简单工具。在它最简单的形式中，它可以从头到尾追踪一个二进制可执行文件，并且输出一行文本，其包含系统调用，参数和每个进程生命周期内的每个系统调用的返回值。而且它能够做更多：

• 它可以基于指定的系统调用或一组系统调用进行过滤。
• 它可以通过统计特定系统调用的使用次数、所花费的时间以及成功和错误的数量来分析系统调用的使用情况。
• 它跟踪发送到进程的信号。
• 它可以通过 pid 附加到任何正在运行的进程。

如果你用过其他Unix系统，这是类似于“truss"。另一个(更全面)是Sun的Dtrace。

如何用它？

此处只做浅显的研究，重要性不分先后。

1. 找出程序启动时读了哪个配置文件

有没有试过弄清楚为什么有些程序没有读取你认为应该读取的配置文件？不得不解决自定义编译的或特定发行版本是从你认为的“错误”的位置读取的配置表吗？朴素的方法：

$ strace php 2>&1 | grep php.ini
open("/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/lib/php.ini", O_RDONLY) = 4
lstat64("/usr/local/lib/php.ini", st_mode=S_IFLNK|0777, st_size=27, ...) = 0
readlink("/usr/local/lib/php.ini", "/usr/local/Zend/etc/php.ini", 4096) = 27
lstat64("/usr/local/Zend/etc/php.ini", st_mode=S_IFREG|0664, st_size=40971, ...) = 0

所以这个版本的PHP从/usr/local/lib/php.ini读取php.ini(但是它首先尝试/usr/local/bin)。如果我只关心特定的系统调用，那么更复杂的方法：

$ strace -e open php 2>&1 | grep php.ini
open("/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/local/lib/php.ini", O_RDONLY) = 4

这相同的方法可以应用于许多其他情况。在不同路径安装多个版本，并且想准确地知道哪个版本被加载了？等等。

2. 为什么这个程序没有打开我的文件？

曾经遇到一个程序，它静默地拒绝读取它没有读取权限的文件，但是你却在咒骂很久之后才发现，因为你曾经认为它实际上没有找到这个文件。好吧，你已经知道该做什么了：

$ strace -e open,access 2>&1 | grep your-filename

查找一个open()或access()系统调用的失败。

3. 此刻进程正在做什么？

曾经有一个进程突然独占大量CPU吗？或者一个进程似乎挂起了？接着你找到pid，然后这样做：

root@dev:~# strace -p 15427
Process 15427 attached - interrupt to quit
futex(0x402f4900, FUTEX_WAIT, 2, NULL 
Process 15427 detached

啊。所以在这种情况下，它挂在一个调用futex()中。顺便说一下，在这种情况下，它没有告诉我们更多——挂在futex上可能由许多事情引起(付特效是一种在linux内核中的锁机制)。以上是来自正常工作但是空闲Apache子进程正在等待被一个请求处理。但是"trace -p"非常有用，因为它消除了许多猜测，并且消除必须重启应用程序来获取更多的打印日志(或者重新编译它)。

4. 时间花在哪里了？

您始终可以在启用分析的情况下重新编译应用程序，并获得准确的信息，尤其是关于您自己的代码的哪些部分将花费时间在你应该做的上。 但通常能够快速将 strace 附加到进程以查看它当前花费时间在哪里，尤其是诊断问题非常有用。 是 90% 的 CPU 使用率是因为它实际上是在做真正的工作，还是因为某些事情失控了。 这是你要做的：

root@dev:~# strace -c -p 11084
Process 11084 attached - interrupt to quit
Process 11084 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 94.59    0.001014          48        21           select
  2.89    0.000031           1        21           getppid
  2.52    0.000027           1        21           time
------ ----------- ----------- --------- --------- ----------------
100.00    0.001072                    63           total
root@dev:~# 

使用-c -p启动strace之后，你只需要等待，然后用ctrl-c退出。Strace将发出性能分析数据。在这种情况下，它是一个空闲的Postgres“postmaster”进程，其大部分时间花在select()的静静等待中。在这种情况下，它在每个select()调用之间调用getppid()和time()，这是相当标准的事件循环。你也能使用“ls”运行“从头到尾”：

root@dev:~# strace -c >/dev/null ls
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 23.62    0.000205         103         2           getdents64
 18.78    0.000163          15        11         1 open
 15.09    0.000131          19         7           read
 12.79    0.000111           7        16           old_mmap
  7.03    0.000061           6        11           close
  4.84    0.000042          11         4           munmap
  4.84    0.000042          11         4           mmap2
  4.03    0.000035           6         6         6 access
  3.80    0.000033           3        11           fstat64
  1.38    0.000012           3         4           brk
  0.92    0.000008           3         3         3 ioctl
  0.69    0.000006           6         1           uname
  0.58    0.000005           5         1           set_thread_area
  0.35    0.000003           3         1           write
  0.35    0.000003           3         1           rt_sigaction
  0.35    0.000003           3         1           fcntl64
  0.23    0.000002           2         1           getrlimit
  0.23    0.000002           2         1           set_tid_address
  0.12    0.000001           1         1           rt_sigprocmask
------ ----------- ----------- --------- --------- ----------------
100.00    0.000868                    87        10 total

与你期待的差不多，它花费大部分时间在两次调用去读目录(仅有两次，由于它运行在一个小目录上)。

5. 为什么我的***无法连接到该服务器？

调试一些进程为什么未能连接远程服务器会让人沮丧。DNS可能失败，连接可能挂起，服务器可能送回一些不符合预期的东西等等。你可以使用tcpdump去分析这么多这样的情况，这也是非常好的工具，但是很多时候strace会让你更加方便，仅是因为它只会返回由你的进程发起的系统调用的相关数据。例如，如果你试图弄清楚连接到同一数据库服务器的数百个正在运行的进程中的一个(在其中挑选出正确的连接进行tcpdump是一场噩梦)，strace让生活变得更轻松。这是一个在端口80上连接到www.news.com的"nc"跟踪示例，没有任何问题：

$ strace -e poll,select,connect,recvfrom,sendto nc www.news.com 80
sendto(3, "\\\\24\\\\0\\\\0\\\\0\\\\26\\\\0\\\\1\\\\3\\\\255\\\\373NH\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0", 20, 0, sa_family=AF_NETLINK, pid=0, groups=00000000, 12) = 20
connect(3, sa_family=AF_FILE, path="/var/run/nscd/socket", 110) = -1 ENOENT (No such file or directory)
connect(3, sa_family=AF_FILE, path="/var/run/nscd/socket", 110) = -1 ENOENT (No such file or directory)
connect(3, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), 28) = 0
poll([fd=3, events=POLLOUT, revents=POLLOUT], 1, 0) = 1
sendto(3, "\\\\213\\\\321\\\\1\\\\0\\\\0\\\\1\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\34\\\\0\\\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([fd=3, events=POLLIN, revents=POLLIN], 1, 5000) = 1
recvfrom(3, "\\\\213\\\\321\\\\201\\\\200\\\\0\\\\1\\\\0\\\\1\\\\0\\\\1\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\34\\\\0\\\\1\\\\300\\\\f"..., 1024, 0, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), [16]) = 153
connect(3, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), 28) = 0
poll([fd=3, events=POLLOUT, revents=POLLOUT], 1, 0) = 1
sendto(3, "k\\\\374\\\\1\\\\0\\\\0\\\\1\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\1\\\\0\\\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([fd=3, events=POLLIN, revents=POLLIN], 1, 5000) = 1
recvfrom(3, "k\\\\374\\\\201\\\\200\\\\0\\\\1\\\\0\\\\2\\\\0\\\\0\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\1\\\\0\\\\1\\\\300\\\\f"..., 1024, 0, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), [16]) = 106
connect(3, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), 28) = 0
poll([fd=3, events=POLLOUT, revents=POLLOUT], 1, 0) = 1
sendto(3, "\\\\\\\\\\\\2\\\\1\\\\0\\\\0\\\\1\\\\0\\\\0\\\\0\\\\0\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\1\\\\0\\\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([fd=3, events=POLLIN, revents=POLLIN], 1, 5000) = 1
recvfrom(3, "\\\\\\\\\\\\2\\\\201\\\\200\\\\0\\\\1\\\\0\\\\2\\\\0\\\\0\\\\0\\\\0\\\\3www\\\\4news\\\\3com\\\\0\\\\0\\\\1\\\\0\\\\1\\\\300\\\\f"..., 1024, 0, sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("62.30.112.39"), [16]) = 106
connect(3, sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("216.239.122.102"), 16) = -1 EINPROGRESS (Operation now in progress)
select(4, NULL, [3], NULL, NULL)        = 1 (out [3])

那么这里会发生什么？注意到与 /var/run/nscd/socket 的连接尝试了吗？他们的意思是 nc 首先尝试连接到 NSCD - 名称服务缓存守护程序 - 通常用于依赖 NIS、YP、LDAP 或类似目录协议进行名称查找的设置。在这种情况下，连接失败。然后它移动到 DNS（DNS 是端口 53，因此在以下连接中是“sin_port=htons(53)”。您可以看到它然后执行“sendto()”调用，发送一个包含 www.news 的 DNS 数据包.com。然后它读回一个数据包。无论出于何种原因，它尝试了三次，最后一次请求略有不同。我最好的猜测是为什么在这种情况下 www.news.com 是一个 CNAME（一个“别名”），并且多个请求可能只是 nc 如何处理它的工件。最后，它最终向它找到的 IP 发出 connect()。注意它返回 EINPROGRESS。这意味着连接是非阻塞的 - nc 想要继续处理。然后它调用select()，连接成功时成功。尝试将“read”和“write”添加到strace的系统调用列表中，并在连接时输入一个字符串，你会得到一些东西像这样：

read(0, "test\\\\n", 1024)                 = 5
write(3, "test\\\\n", 5)                   = 5
poll([fd=3, events=POLLIN, revents=POLLIN, fd=0, events=POLLIN], 2, -1) = 1
read(3, "\\"-//IETF//"..., 1024) = 216
write(1, "\\"-//IETF//"..., 216) = 216

这表明它从标准输入读取“测试”+换行，并将其写回网络连接，然后调用 poll() 等待回复，从网络连接读取回复并将其写入标准输出。 一切似乎都正常