2017，科学使用strace神器（附代码，举栗子）

　　我感到惊讶，都2017年了，几乎没有人知道他们可以使用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，访问2>＆1 | grep your-filename

查找失败的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 /调用调用错误syscall
------ ----------- ----------- --------- --------- ---- ------------
 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 /调用调用错误syscall
------ ----------- ----------- --------- --------- ---- ------------
 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关闭
  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 11 rt_sigprocmask
------ ----------- ----------- --------- --------- ---- ------------
100.00 0.000868 87 10总计

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

5）为什么****不能连接到该服务器？

调试为什么一些进程不连接到远程服务器可能是非常令人沮丧。DNS可能会失败，连接可能挂起，服务器可能会发送意外回来等。你可以使用tcpdump分析很多，这也是一个非常好的工具，但很多时间strace会给你较少的颤振，只是因为它只会返回与“你的”进程生成的系统调用相关的数据。如果你想知道连接到同一个数据库服务器的几百个运行进程中的哪一个（例如，选择与tcpdump的正确连接是一个噩梦），strace使生活更容易。这是一个“nc”跟踪的示例，连接到www.news.com在端口80上没有任何问题：

$ 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（）”调用，发送一个DNS数据包，包含www.news .com它读回一个数据包，无论什么原因，它尝试三次，最后一个有一个稍微不同的请求。我最好猜猜为什么在这种情况下，www.news.com是一个CNAME（一个“别名”），并且多个请求可能只是一个nc处理的工件，然后最终，它最终发出一个connect（）到它找到的IP。注意它返回EINPROGRESS。这意味着连接是非阻塞的 - nc想要继续处理。然后调用select（），当连接成功时，它成功。尝试添加“读”和“写”到给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

这显示它从标准读取“test”+ linefeed，并将其写回网络连接，然后调用poll（）等待答复，从网络连接读取答复并将其写入标准输出。一切似乎工作正常。

 

参数：

-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执行被跟踪的命令

 

举个栗子

　　我的php出现了未知问题，error只有 ：Fatal error: Allowed memory size of * bytes exhausted (tried to allocate * bytes) in.

　　我想知道发现什么了，然后打开我的mac, show you my code!

killall -9 php-fpm &&  strace -ff -o strace.log  -f -F     -T /usr/local/sinawap/php-fpm/sbin/php-fpm -c  /usr/local/sinawap/php-fpm/lib/php.gray.ini

　　命令就不用解释了吧，然后看看惊喜：

　　

 

　　没错，就看byte数最多的， 

less strace.log.5325

　　发现大量的循环调用，

sendto(10, "set icmsa_page_125221_vt_4_14891"..., 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000022>

recvfrom(10, 0x29f8fc0, 8196, 16384, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>

poll([{fd=10, events=POLLIN}], 1, 1500) = 1 ([{fd=10, revents=POLLIN}]) <0.000109>

recvfrom(10, "STORED\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 8 <0.000013>

sendto(10, "get icmsa_page_125221_vt_4_14891"..., 44, MSG_NOSIGNAL, NULL, 0) = 44 <0.000028>

recvfrom(10, 0x29f8fc0, 8196, 16384, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>

poll([{fd=10, events=POLLIN}], 1, 1500) = 1 ([{fd=10, revents=POLLIN}]) <0.000013>

recvfrom(10, "VALUE icmsa_page_125221_vt_4_148"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 66 <0.000013>

rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000013>

rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x37a0832920}, 8) = 0 <0.000013>

rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000013>

nanosleep({1, 0}, 0x7fffd5683470)           = 0 <1.000160>

sendto(10, "get icmsa_page_125221_vt_4_14891"..., 44, MSG_NOSIGNAL, NULL, 0) = 44 <0.000080>

recvfrom(10, "END\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 5 <0.000103>

sendto(10, "set icmsa_page_125221_vt_4_14891"..., 61, MSG_NOSIGNAL, NULL, 0) = 61 <0.000077>

recvfrom(10, "STORED\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 8 <0.000108>

sendto(10, "delete icmsa_page_125221_vt_4_14"..., 47, MSG_NOSIGNAL, NULL, 0) = 47 <0.000026>

　　　仔细对照下php代码，发现我的PHP yar 的外部类API_Current存在循环调用，导致内存烧尽！！

　　　通过快速定位后，很快fix了这个bug! 

　　

其他想法？

　　如果你以特别创意的方式使用strace，我很乐意听到你的声音。哈哈