运维利器：万能的strace(2)

-tt 在每行输出的前面,显示毫秒级别的时间
-T 显示每次系统调用所花费的时间
-v 对于某些相关调用,把完整的环境变量,文件stat结构等打出来.
-f 跟踪目标进程,以及目标进程创建的所有子进程
-e 控制要跟踪的事件和跟踪行为,比如指定要跟踪的系统调用名称
-o 把strace的输出单独写到指定的文件
-s 当系统调用的某个参数是字符串时,最多输出指定长度的内容,默认是32个字节
-p 指定要跟踪的进程pid,要同时跟踪多个pid,重复多次-p选项即可.

实例：跟踪nginx,看其启动时都访问了哪些文件

strace -tt -T -f -e trace=file -o /data/log/strace.log -s 1024 ./nginx

部分输出:

输出中,第一列显示的是进程的pid,接着是毫秒级别的时间,这个是-tt 选项的效果.

每一行的最后一列,显示了该调用所花的时间,是-T选项的结果.

这里的输出只显示和文件访问有关的内容,这是因为我们通过-e trace=file 选项指定了.

strace问题定位案例

1、定位进程异常退出

问题：机器上有个叫做run.sh的常驻脚本,运行一分钟后会死掉.需要查出死因.

定位：进程还在运行时,通过ps命令获取其pid,假设我们得到的pid是24298

strace -o strace.log -tt -p 24298

查看strace.log,我们在最后2行看到如下内容:

22:47:42.803937 wait4(-1,?<unfinished …>

22:47:43.228422 +++ killed by SIGKILL +++

这里可以看出,进程是被其他进程用KILL信号杀死的.

实际上,通过分析,我们发现机器上别的服务有个监控脚本,它监控一个也叫做run.sh的进程,当发现run.sh进程数大于2时,就会把它杀死重启.结果导致我们这个run.sh脚本被误杀.

进程被杀退出时,strace会输出killed by SIGX(SIGX代表发送给进程的信号)等,那么,进程自己退出时会输出什么呢?

这里有个叫做test_exit的程序,其代码如下:

#include <stdio.h>

#include <stdlib.h>

int main(int argc,char **argv) {

exit(1);

}

我们strace看下它退出时strace上能看到什么痕迹.

strace -tt -e trace=process -f ./test_exit

说明: -e trace=process 表示只跟踪和进程管理相关的系统调用.

输出：

23:07:24.672849 execve(“./test_exit”,[“./test_exit”],[/* 35 vars */]) = 0

23:07:24.674665 arch_prctl(ARCH_SET_FS,0x7f1c0eca7740) = 0

23:07:24.675108 exit_group(1) ? ? ? ? ? = ?

23:07:24.675259 +++ exited with 1 +++

可以看出,进程自己退出时(调用exit函数,或者从main函数返回),最终调用的是exit_group系统调用,并且strace会输出exited with X(X为退出码).

可能有人会疑惑,代码里面明明调用的是exit,怎么显示为exit_group?

这是因为这里的exit函数不是系统调用,而是glibc库提供的一个函数,exit函数的调用最终会转化为exit_group系统调用,它会退出当前进程的所有线程.实际上,有一个叫做_exit()的系统调用(注意exit前面的下划线),线程退出时最终会调用它.

2、定位共享内存异常

有个服务启动时报错：

shmget 267264 30097568: Invalid argument
Can not get shm...exit!

错误日志大概告诉我们是获取共享内存出错,通过strace看下：

strace -tt -f -e trace=ipc ./a_mon_svr ? ? ../conf/a_mon_svr.conf

输出：

22:46:36.351798 shmget(0x5feb,12000,0666) = 0

22:46:36.351939 shmat(0,0) ? ? ? ? ?= ?

Process 21406 attached

22:46:36.355439 shmget(0x41400,30097568,0666) = -1 EINVAL (Invalid argument)

shmget 267264 30097568: Invalid argument

Can not get shm…exit!

这里,我们通过-e trace=ipc 选项,让strace只跟踪和进程通信相关的系统调用.

从strace输出,我们知道是shmget系统调用出错了,errno是EINVAL.同样,查询下shmget手册页,搜索EINVAL的错误码的说明:

EINVAL A new segment was to be created and size < SHMMIN or size >

SHMMAX,or no new segment was to be created,a segment with given key existed,

but size is greater than the size of that segment

翻译下,shmget设置EINVAL错误码的原因为下列之一：

• 要创建的共享内存段比 SHMMIN小 (一般是1个字节)
• 要创建的共享内存段比 SHMMAX 大 (内核参数kernel.shmmax配置)
• 指定key的共享内存段已存在,其大小和调用shmget时传递的值不同.

从strace输出看,我们要连的共享内存key 0x41400,指定的大小是30097568字节,明显与第1、2种情况不匹配.那只剩下第三种情况.使用ipcs看下是否真的是大小不匹配：

ipcs ?-m | grep 41400

key ? ? ? ?shmid ? ? ?owner ? ? ?perms ? ? ?bytes ? ? ?nattch ? ? status

0x00041400 1015822 ? ?root ? ? ? 666 ? ? ? ?30095516 ? 1

可以看到,已经0x41400这个key已经存在,并且其大小为30095516字节,和我们调用参数中的30097568不匹配,于是产生了这个错误.

在我们这个案例里面,导致共享内存大小不一致的原因,是一组程序中,其中一个编译为32位,另外一个编译为64位,代码里面使用了long这个变长int数据类型.

把两个程序都编译为64解决了这个问题.

这里特别说下strace的-e trace选项.

要跟踪某个具体的系统调用,-e trace=xxx即可.但有时候我们要跟踪一类系统调用,比如所有和文件名有关的调用、所有和内存分配有关的调用.

（编辑：ASP站长网）