程序分析利器strace 简介 strace可以通过捕捉记录正在运行进程的系统调用和信号来进行程序分析，既然是系统调用，因此shell脚本和应用程序都可以通过strace来调试分析。
strace是一个非常方便有用的诊断，调试工具，我们不需要重新编译程序，通过strace追踪便可获得系统底层发生的文件管理，进程管理，内存分配，信号捕捉等事件。比如有的时候内存泄露我们无法从日志中发现异常，因此需要更加底层的内存分配管理调用来分析。
打印 在strace捕捉到每行记录中都包含系统调用名字，参数和返回值，也可以通过参数打印很多的调用细节，比如所属进程，调用开始和消耗时间。捕捉到的所有信息我们可以输出到标准输出，也可以输出到指定文件。
系统调用生命周期标记 在追踪多个进程和线程的系统调用过程中，当A系统调用执行一段时候后，此时B系统调用开始执行，我们通过unfinished标记调用的开始，resumed来标记调用的结束
1 2 3 16308 14 :47 :31.092116 mmap2(NULL , 19480576 , PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1 , 0 <unfinished ...>15606 14 :47 :31.092137 clock_gettime(CLOCK_REALTIME, <unfinished ...>16308 14 :47 :31.092153 <... mmap2 resumed> ) = 0x842e9000 <0.000022 >
结构体参数/返回值打印 结构体使用花括号括起来，并使用空格分离
比如clock_gettime，函数原型为：
1 int clock_gettime (clockid_t clk_id, struct timespec *tp)
系统调用显示为：
1 2 3 15606 14 :47 :31.093987 clock_gettime(CLOCK_REALTIME, <unfinished ...>16308 14 :47 :31.094002 <... futex resumed> ) = 1 <0.000023 >15606 14 :47 :31.094019 <... clock_gettime resumed> {tv_sec=403766673093154435 , tv_nsec=7593356726744084332 }) = 0 <0.000023 > >>返回结果
最终timespec结构体结果打印为
1 {tv_sec=403766673093154435 , tv_nsec=7593356726744084332 }
数组成员打印 数组使用方括号括起来，并使用空格分离
比如execve
1 execve("/bin/sh", ["sh", "-c", "sleep 2"], [/* 30 vars */]) = 0 <0.000135>
使用 执行方式 strace有两种执行方式
第一种strace + 程序，比如
1 strace sleep 5 >>strace +shell命令
或者
1 $ strace test-run >>strace +可执行二进制程序
或者
1 strace ./test.sh >>strace +shell脚本
第二种为 strace -p PID，比如
有一个正在运行的程序./test-run， 获取该程序的进程号
1 2 test/ $ pidof test-run 66725 66723
之后追踪此进程
1 2 3 $ sudo strace -p 66723 [10:26:57] strace: Process 66723 attached restart_syscall(<... resuming interrupted nanosleep ...>) = 0 write(1, "in father pid: 66723 to sleep\n", 31) = 31
选项 下面是最常用的使用搭配
1 strace -o output.txt -T -tt -p 28979 -f
按照使用频率来进行记录
-o 文件 指定日志输出文件，实际项目追踪过程中几分钟内会产生上百万行日志，如果输出到屏幕，可能会导致键盘控制无效或者控制终端崩溃等，也不利于浏览和过滤关键信息，因此最好将系统调用记录输出重定向到文件，但是进程执行的输出依旧显示在屏幕。
-T 在最右端打印系统调用时间
1 2 3 4 test/ $ strace -T sleep 2 ... nanosleep({2, 0}, NULL) = 0 <2.000731> >>系统调用时间为2.000731s ...
-tt 在最左端打印调用时的时间戳，微妙级
1 2 3 4 test/ $ strace -T -tt sleep 2 10:54:49.461790 nanosleep({2, 0}, NULL) = 0 <2.000594> 10:54:51.462440 close(1) = 0 <0.000016> 10:54:51.462500 close(2) = 0 <0.000014>
-f/-F -F同-f功能一致，都是打印进程号，包括fork的子进程和线程
1 2 3 4 5 6 7 8 9 10 test/ $ strace -T -tt -f test-run 11:10:23.994700 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3fa30db9d0) = 70544 <0.000051> >>通过fork创建子进程，并返回子进程号 11:10:23.994772 getpid() = 70543 <0.000006> >>父进程获取自己的进程号 11:10:23.994794 write(1, "in father pid: 70543 start to sl"..., 36in father pid: 70543 start to sleep ) = 36 <0.000076> strace: Process 70544 attached >>strace开始追踪子进程70544 [pid 70543] 11:10:23.994981 nanosleep({10, 0}, <unfinished ...> >>父进程开始睡眠 [pid 70544] 11:10:23.995047 write(1, "in child pid: 70544 start to sle"..., 35in child pid: 70544 start to slepp >>子进程系统调用 ) = 35 <0.000024>
-ff 将追踪的多进程的系统调用记录重定向到不同的文件，需要搭配-o 使用，比如指定 -o output.txt, 会生成output.txt.PID，但是进程执行的输出依旧显示在屏幕
1 2 3 4 5 6 7 test/ $ strace -T -tt -f -o output.txt test-run >>进程打印 START TO RUN SUB_MODULE: fork >>开始fork子进程 in father pid: 71278 start to sleep >>父进程pid为71278 in child pid: 71279 start to sleep >>子进程pid为71279 in child pid: 71279 end to sleep in father pid: 71278 to sleep
最终生成文件为output.txt.71278和output.txt.71279
-i 打印系统调用时的指令地址
1 2 3 4 5 test/ $ strace -i sleep 2 [00007f067d4d4370] nanosleep({2 , 0 }, NULL) = 0 [00007f067d48035b] close(1 ) = 0 [00007f067d48035b] close(2 ) = 0
-b -b syscall，当指定的系统调用被捕捉时，将该进程从strace中脱离，目前只支持execve， 对带有-f 的选项的有用，这样可以不看子进程的调用， 但是可以是看多线程的系统调用。比如system函数的调用
1 2 3 4 5 6 int main () printf ("hello world start \n" ); system("sleep 2" ); printf ("hello world start \n" ); return 0 ; }
比如以上代码system函数在fork子进程之后通过execve来执行 sleep 2这条shell命令
1 2 3 4 5 6 7 8 9 14 :35 :16.278634 clone(child_stack=0 , flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0x7fff0f8f096c ) = 156737 <0.000051 > >>fork通过clone创建子进程14 :35 :16.278699 wait4(156737 , strace: Process 156737 attached <unfinished ...> >>strace捕捉子进程syscall [pid 156737] 14 :35 :16.278755 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7fbedb1de4c0 }, NULL, 8 ) = 0 <0.000007 >[pid 156737] 14 :35 :16.278776 rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7fbedb1de4c0 }, NULL, 8 ) = 0 <0.000006 >[pid 156737] 14 :35 :16.278795 rt_sigprocmask(SIG_SETMASK, [], NULL, 8 ) = 0 <0.000007 >[pid 156737] 14 :35 :16.278820 execve("/bin/sh" , ["sh" , "-c" , "sleep 2" ], []strace: Process 156737 detached >>捕捉到子进程的execve信号，然后脱离进程 <detached ...> 14 :35 :18.281459 <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0 }], 0 , NULL) = 156737 <2.002757 >
-e -e expr 指定捕捉指定类型的系统调用
表达式 说明 -e trace=set 跟踪指定的系统调用 -e trace=file 跟踪文件相关的系统调用（文件名作参数） -e trace=process 跟踪进程相关的系统调用 -e trace=network 跟踪网络相关的系统调用 -e trace=ipc 跟踪进程通讯相关的系统调用 -e trace=desc 根据文件描述符的系统调用 -e trace=memory 跟踪内存相关的系统调用 -e raw=set 将制定的系统调用参数16进制打印出来 实践ok -e signal=set 追踪指定的信号 未实验成功 -e signal=SIGCHLD -e read=3,5 输出从指定文件句柄read出的内容 实践ok -e write=set 输出写入到指定文件句柄的内容 实践ok
1 2 3 4 5 6 7 test/ $ strace -e write=1,2 -T -tt -f ./hello-world ... 15:16:44.543954 write(1, "hello world start \n", 19hello world start ) = 19 <0.000009> | 00000 68 65 6c 6c 6f 20 77 6f 72 6c 64 20 73 74 61 72 hello world star | | 00010 74 20 0a ...
-c/-C 统计系统调用时间，但是不会打印普通的输出， -C既有普通的输出，也会在最后进行系统调用个数统计
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 test/ $ sudo strace -c sleep 2 [15:23:57] % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 1 read 0.00 0.000000 0 3 open 0.00 0.000000 0 5 close 0.00 0.000000 0 3 fstat 0.00 0.000000 0 8 mmap 0.00 0.000000 0 4 mprotect 0.00 0.000000 0 1 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 3 3 access 0.00 0.000000 0 1 nanosleep 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 34 3 total
access系统调用失败是我本地电脑没有一些系统库
-w 统计系统调用开始和结束的时间差，和-c搭配使用
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 test/ $ sudo strace -c -w sleep 2 [15:28:41] % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 99.98 2.000670 2000670 1 nanosleep 0.00 0.000096 96 1 execve 0.00 0.000058 7 8 mmap 0.00 0.000032 6 5 close 0.00 0.000031 8 4 mprotect 0.00 0.000025 8 3 open 0.00 0.000021 7 3 3 access 0.00 0.000020 7 3 brk 0.00 0.000018 6 3 fstat 0.00 0.000010 10 1 munmap 0.00 0.000006 6 1 read 0.00 0.000006 6 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 2.000993 34 3 total
能发现进程大部分时间都用在nanosleep上，可以用来检查性能瓶颈并针对优化
-S 对-c统计的数据进行排序，比如默认是时间，也可以是名字和系统调用次数,时间
比如对调用次数进行排序
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 strace -c -w -S calls sleep 2 [15:28:50] % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000057 7 8 mmap 0.00 0.000042 8 5 close 0.00 0.000033 8 4 mprotect 0.00 0.000026 9 3 open 0.00 0.000020 7 3 fstat 0.00 0.000019 6 3 brk 0.00 0.000021 7 3 3 access 0.00 0.000007 7 1 read 0.00 0.000010 10 1 munmap 99.98 2.000387 2000387 1 nanosleep 0.00 0.000090 90 1 execve 0.00 0.000006 6 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 2.000718 34 3 total
对syscall所用时间排序
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 test/ $ strace -C -w -S time sleep 2 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 99.98 2.001845 2001845 1 nanosleep 0.01 0.000108 108 1 execve 0.00 0.000057 7 8 mmap 0.00 0.000049 10 5 close 0.00 0.000030 8 4 mprotect 0.00 0.000030 10 3 3 access 0.00 0.000024 8 3 open 0.00 0.000019 6 3 fstat 0.00 0.000019 6 3 brk 0.00 0.000010 10 1 munmap 0.00 0.000006 6 1 read 0.00 0.000006 6 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 2.002203 34 3 total
应用 N项目遇到超夜拍照内存泄露，对比检查进程smap发现泄露地址，通过地址对比strace抓取mmap系统调用记录，获取该地址内存申请线程和上下文执行状态，确定内存泄露程序范围。