进程对用户来说就是一个黑盒,strace就是打开这个黑盒子的工具,可以解析出我们需要的调用
使用实例
strace -tt -T -v -f -e trace=file -o /data/log/strace.log -s 1024 -p 23489
-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
# -e trace=file 显示和文件访问相关的调用
-e的拓展
要跟踪某个具体的系统调用,-e trace=xxx即可。但有时候我们要跟踪一类系统调用,比如所有和文件名有关的调用、所有和内存分配有关的调用。
如果人工输入每一个具体的系统调用名称,可能容易遗漏。于是strace提供了几类常用的系统调用组合名字。
-e trace=file 跟踪和文件访问相关的调用(参数中有文件名) -e trace=process 和进程管理相关的调用,比如fork/exec/exit_group -e trace=network 和网络通信相关的调用,比如socket/sendto/connect -e trace=signal 信号发送和处理相关,比如kill/sigaction -e trace=desc 和文件描述符相关,比如write/read/select/epoll等 -e trace=ipc 进程见同学相关,比如shmget等
排查进程问题
vim启动慢
从命令行运行vim后,要等待近半分钟才能进入编辑界面,而且没有任何错误输出。仔细检查了.vimrc和所有的vim脚本都没有错误配置,在网上也找不到类似问题的解决办法,难不成要hacking source code?没有必要,用truss就能找到问题所在:
# strace -f -tt -T -o vim.truss vim
这里-tt -T参数的作用是:在每行输出前加上相对时间戳,即每执行一条系统调用所耗费的时间。我们只要关注哪些系统调用耗费的时间比较长就可以了,用less仔细查看输出文件vim.truss,很快就找到了疑点:
735: 0.000021511 socket(0x2,0x1,0x0) = 4 (0x4)
735: 0.000014248 setsockopt(0x4,0x6,0x1,0xbfbfe3c8,0x4) = 0 (0x0)
735: 0.000013688 setsockopt(0x4,0xffff,0x8,0xbfbfe2ec,0x4) = 0 (0x0)
735: 0.000203657 connect(0x4,{ AF_INET 10.57.18.27:6000 },16) ERR#61 'Connection refused'
735: 0.000017042 close(4) = 0 (0x0)
735: 1.009366553 nanosleep(0xbfbfe468,0xbfbfe460) = 0 (0x0)
735: 0.000019556 socket(0x2,0x1,0x0) = 4 (0x4)
735: 0.000013409 setsockopt(0x4,0x6,0x1,0xbfbfe3c8,0x4) = 0 (0x0)
735: 0.000013130 setsockopt(0x4,0xffff,0x8,0xbfbfe2ec,0x4) = 0 (0x0)
735: 0.000272102 connect(0x4,{ AF_INET 10.57.18.27:6000 },16) ERR#61 'Connection refused'
735: 0.000015924 close(4) = 0 (0x0)
735: 1.009338338 nanosleep(0xbfbfe468,0xbfbfe460) = 0 (0x0)
vim试图连接10.57.18.27这台主机的6000端口(第四行的connect()),连接失败后,睡眠一秒钟继续重试(第6行的nanosleep())。以上片断循环出现了十几次,每次都要耗费一秒多钟的时间,这就是vim明显变慢的原因。可是,你肯定会纳闷:“vim怎么会无缘无故连接其它计算机的6000端口呢?"。问得好,那么请你回想一下6000是什么服务的端口?没错,就是X Server。看来vim是要把输出定向到一个远程X Server,那么Shell中肯定定义了DISPLAY变量,查看.cshrc,果然有这么一行: setenv DISPLAY ${REMOTEHOST}:0,把它注释掉,再重新登录,问题就解决了。
定位进程异常退出
- 问题:机器上有个叫做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为退出码)。
定位共享内存异常
有个服务启动时报错:
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, 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
0x00041400 1015822 root 666 30095516 1
可以看到,已经0x41400这个key已经存在,并且其大小为30095516字节,和我们调用参数中的30097568不匹配,于是产生了这个错误。
- 在我们这个案例里面,导致共享内存大小不一致的原因,是一组程序中,其中一个编译为32位,另外一个编译为64位,代码里面使用了long这个变长int数据类型。
- 把两个程序都编译为64解决了这个问题。
分析性能
假如有个需求,统计Linux 4.5.4 版本内核中的代码行数(包含汇编和C代码)。这里提供两个Shell脚本实现:
poor_script.sh:
!/bin/bash
total_line=0
while read filename; do
line=$(wc -l $filename | awk ‘{print $1}’)
(( total_line += line ))
done < <( find linux-4.5.4 -type f ( -iname ‘.c’ -o -iname ‘.h’ -o -iname ‘*.S’ ) )
echo “total line: $total_line”
good_script.sh:
!/bin/bash
find linux-4.5.4 -type f ( -iname ‘.c’ -o -iname ‘.h’ -o -iname ‘*.S’ ) -print0 \
| wc -l —files0-from - | tail -n 1
- 两段代码实现的目的是一样的。 我们通过strace的-c选项来分别统计两种版本的系统调用情况和其所花的时间(使用-f同时统计子进程的情况)
从两个输出可以看出,good_script.sh 只需要2秒就可以得到结果:19613114行。它大部分的调用(calls)开销是文件操作(read/open/write/close)等,统计代码行数本来就是干这些事情。
而poor_script.sh完成同样的任务则花了539秒。它大部分的调用开销都在进程和内存管理上(wait4/mmap/getpid…)。
实际上,从两个图中clone系统调用的次数,我们可以看出good_script.sh只需要启动3个进程,而poor_script.sh完成整个任务居然启动了126335个进程!
而进程创建和销毁的代价是相当高的,性能不差才怪。