五种利用strace查故障的简单方法

水深无声 2022-05-15 15:46 235阅读 0赞

来源：[http://hokstad.com/5-simple-ways-to-troubleshoot-using-strace][http_hokstad.com_5-simple-ways-to-troubleshoot-using-strace]

我很惊讶很少有人知道他们可以使用的所有东西。它总是我提出的第一个调试工具之一，因为它通常在我运行的Linux系统上可用，它可以用来解决各种各样的问题。

# 什么是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（没有这样的文件或目录）
    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（没有这样的文件或目录）
    open（“/ usr / local / lib / php.ini”，O_RDONLY）= 4

同样的方法适用于许多其他事情。在不同的路径上安装了多个版本的库，并确切地想知道实际加载了哪些库？等等

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

曾经遇到过一个程序，它默默地拒绝阅读它没有读取权限的文件，但你只是在发誓多年后才弄明白，因为你认为它实际上并没有找到文件？好吧，你已经知道该怎么做了：

$ strace -e open，access 2>＆1 | grep你的文件名

查找失败的open（）或access（）系统调用

## **3）现在正在做什么的过程是什么？** ##

曾经有一个过程突然大量的CPU？或者有一个过程似乎挂？然后你找到了pid，然后这样做：

root @ dev ：〜＃strace -p 15427
    附加过程15427  - 中断退出
    futex（0x402f4900，FUTEX_WAIT，2，NULL 
    过程15427分离

啊。所以在这种情况下它挂在对futex（）的调用中。顺便提一下，在这种情况下它并没有告诉我们这么多 - 挂在futex上可能是由许多事情引起的（futex是Linux内核中的锁定机制）。以上是来自正常工作但空闲的Apache子进程，它只是等待递交请求。但是“strace -p”非常有用，因为它消除了大量的猜测，并且通常无需使用更广泛的日志记录重新启动应用程序（甚至重新编译它）。

## **4）什么是时间？** ##

您始终可以重新编译打开了性能分析的应用程序，并获取准确的信息，尤其是您自己的代码的哪些部分需要花费时间，这应该是您应该做的。但是，能够快速将strace附加到流程以查看**当前**花费的时间，特别是诊断问题，这通常非常有用。这是90％的CPU使用，因为它实际上是在做实际工作，或者是失控的东西。这是你做的：

root @ dev ：〜＃strace -c -p 11084
    附加过程11084  - 中断退出
    过程11084分离
    ％time秒usecs / call calls错误系统调用
    ------ ----------- ----------- --------- --------- ---- ------------
     94.59 0.001014 48 21选择
      2.89 0.000031 1 21 getppid
      2.52 0.000027 1 21次
    ------ ----------- ----------- --------- --------- ---- ------------
    总计100.00 0.001072 63
    root @ dev ：〜＃

在你使用-c -p开始strace之后，只要你愿意，就等待，然后用ctrl-c退出。如上所述，Strace将吐出分析数据。在这种情况下，它是一个空闲的Postgres“postmaster”进程，它花费大部分时间静静地等待select（）。在这种情况下，它在每个select（）调用之间调用getppid（）和time（），这是一个相当标准的事件循环。您也可以使用“ls”运行此“开始结束”：

root @ dev ：〜＃strace -c> / dev / null ls
    ％time秒usecs / call calls错误系统调用
    ------ ----------- ----------- --------- --------- ---- ------------
     23.62 0.000205 103 2 getdents64
     18.78 0.000163 15 11 1开放
     15.09 0.000131 19 7阅读
     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访问
      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写
      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总计

几乎是你所期望的，它花费大部分时间在两次调用中读取目录条目（因为它在一个小目录上运行，所以只有两次）。

## **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（没有这样的文件或目录）
    connect（3，{sa_family = AF_FILE，path =“/ var / run / nscd / socket”}，110）= -1 ENOENT（没有这样的文件或目录）
    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（正在进行中的操作）
    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数据包然后它会回读一个数据包。无论出于何种原因它会尝试三次，最后一次请求稍有不同。我最好猜测为什么在这种情况下www.news.com是一个CNAME（一个“别名”），并且多个请求可能只是nc如何处理它的工件。然后最后，它最终向它找到的IP发出connect（）。注意它返回EINPROGRESS。这意味着连接是非阻塞的 - nc想要继续处理。然后调用select（），在连接成功时成功。尝试将“read”和“write”添加到给strace的系统调用列表中，并在连接时输入一个字符串，你会得到这样的结果：

读（0，“test \\ n”，1024）= 5
    写（3，“test \\ n”，5）= 5
    poll（[{fd = 3，events = POLLIN，revents = POLLIN}，{fd = 0，events = POLLIN}]，2，-1）= 1
    read（3，“\” -  // IETF //“......，1024）= 216
    写（1，“\” -  // IETF //“......，216）= 216

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

[http_hokstad.com_5-simple-ways-to-troubleshoot-using-strace]: http://hokstad.com/5-simple-ways-to-troubleshoot-using-strace
[Dtrace]: http://opensolaris.org/os/community/dtrace/