使用strace工具故障排查的5种简单方法

时间 2020-01-27

标签使用 strace 工具故障排查简单方法繁體版

原文原文链接

strace 是一个很是简单的工具，用来跟踪可执行程序的系统调用(system call)。最简单的使用是，它追踪可行程序运行时的整个生命周期，输出每个系统调用的名字，参数和返回值。 php

可是它还能够作更多的事情：服务器

它能够基于系统调用或者系统调用组来过滤网络

它能够经过计算制定系统调用的次数，花费的时间以及成功和失败的次数来描述系统调用的使用socket

它能够追踪发送给进程的信号(signal)tcp

它能够经过进程id(pid)号加入到任意正在运行的进程上ide

如何使用函数

这里只是简单的描述strace如何使用，并不打算对此作深刻分析工具

找出一个程序启动时读取了哪一个配置文件post

有的时候，你发发现，不管你如何修改配置文件，应用程序并无按照你的思路去运行，这是什么缘由？一个浅显但容易忽视的考虑是，应用程序启动时读取了你认为要读取的配置文件了吗？看下面的例子：ui

$ 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/bin/下读取php.ini文件，也许不是你想的首先从/usr/local/lib/下读取。

上述的输出会不少，咱们甚至能够经过参数来指定只追踪咱们关心的系统调用，相似以下：

$ 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

为何程序没有打开个人文件？

每个可执行程序读取文件时，若是权限不够，则会遭拒绝。而若是文件找不到，也并不会报错，除非你在程序里设置了错误处理，So，若是程序没有读取个人文件，我该如何跟踪呢？

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

检查open()和access()系统调用的输出结果，看看是什么缘由

进程此刻正在作什么？

你的程序忽然消耗了大量的CPU，或者程序彷佛被挂起了，那么咱们经过进程的pid号看看此刻它正在作什么

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

经过跟踪，你知道程序挂起的缘由是正在调用futex()。

程序的时间花在什么地方

你老是但愿程序可以按照你的意愿去工做，也但愿它能在正确的时间作正确的事情，甚至但愿它是最优的，尽量在程序运行的周期内，消耗的90%以上的资源都是在作须要作的事情，而不是简单的等待。也许，下面的这个指令能够帮上你的忙:

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:~#

若是你是跟踪的后台守护进程，能够经过上面的指令跟踪一段时间，而后按ctrl+c退出，strace会根据得到信息描述出上面的结果。

上述的例子说明当前进程(postmaster)最要的时间花在等待select()函数上，在每调用一次select函数后，它分别调用getpid函数和time函数. 若是是非后台守护进程，那strace能够跟踪进程的开始至结束，相似下面这样：

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

ls程序大部分时间花在读取目录条目上面。

为何我不能链接到服务器？

调试进程不能链接到服务器是一个痛苦的事情，由于缘由不少，好比DNS失效啦，链接被挂起啦，服务器返回异常数据啦，服务器自己异常啦，等等。通常网络调试方面，不少人会想到另一个很是不错的工具-tcpdump。但它的参数太多了，并且你要从上百个链接进程中找出其中一个进程为何不能链接恐怕是一件很是费力的工做。strace 其实也能在这种情景下帮上你的忙，它仅仅输出与系统调用相关的数据，从而可让咱们的注意力更集中。相似下面这样：

$ 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_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- Name Service Cache Daemon - 它一般用于设置和NIS，YP，LDAP或者相似目录协议相关的域名查询配置上。在上述例子中，链接失败了。

接下来进程开始链接到DNS，这点能够从sin_port=htons(53)输出能够看出。你能够看到，它接着作了一个sendto()的调用，发出了一个包含www.news.com信息的DNS包。而后读取返回的包数据，不知什么缘由，它作了三次这样的尝试。一个可能的缘由是www.news.com是一条CNAME记录。屡次请求多是nc程序处理的一种方式。

最后，它总算是发起了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, "

上述表示它从读取”test” + 标准输入的一行信息，而后写入网络链接，接着调用poll来等待回应，而后读取网络反馈的信息并写到标准输出。