linux strace - 追踪系统调用
- - Linux - 操作系统 - ITeye博客有时候发现有个别进程占用了大量CPU或者内存，我们可以查看进程的调用情况. 已有 0 人发表留言，猛击->> 这里<<-参与讨论. —软件人才免语言低担保 赴美带薪读研.
Linux 中用 strace 追踪系统调用和信号值
标签：
linux
strace
系统调用
| 发表时间：2013-02-28 22:14 | 作者：iTech
出处：http://www.cnblogs.com/itech/
原文地址： http://www.dbabeta.com/2009/strace.html
什么是strace
打开man strace，我们能看到对strace的最简洁的介绍就是”strace – trace system calls and signals”。实际上strace是一个集诊断、调试、统计与一体的工具，我们可以使用strace对应用的系统调用和信号传递的跟踪结果来对应用进行分析，以达到解决问题或者是了解应用工作过程的目的。当然strace与专业的调试工具比如说gdb之类的是没法相比的，因为它不是一个专业的调试器。
strace的最简单的用法就是执行一个指定的命令，在指定的命令结束之后它也就退出了。在命令执行的过程中，strace会记录和解析命令进程的所有系统调用以及这个进程所接收到的所有的信号值。
命令的使用方法如下
| 1 2 3 4 5 6 7 | strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ... [ -ofile ] [-ppid ] ... [ -sstrsize ] [ -uusername ] [ -Evar=val ] ... [ -Evar ]... [command[ arg ... ] ] strace -c [ -eexpr ] ... [ -Ooverhead ] [ -Ssortby ] [command[ arg... ] ] |
strace的基本用法
追踪系统调用
现在我们做一个很简单的程序来演示strace的基本用法。这个程序的C语言代码如下：
| 1 2 3 4 5 6 7 8 9 10 | # filename test.c #include <stdio.h> int main() { inta; scanf("%d", &a); printf("%09d\n", a); return0; } |
然后我们用gcc -o test test.c编译一下，得到一个可执行的文件test。然后用strace调用执行
| 1 | strace ./test |
执行期间会要求你输入一个整数，我们输入99，最后得到如下的结果：
| 1 2 | //直接执行test的结果 oracle@orainst[orcl]:~ $./test |
| 1 2 3 | // 执行的结果 99 000000099 |
| 1 2 | //通过strace执行test的结果 oracle@orainst[orcl]:~ $strace ./test |
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 | // strace的trace结果 execve("./test", ["./test"], [/* 41 vars */]) = 0 uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0 brk(0) = 0x8078000 fstat64(3, {st_mode=S_IFREG|0644, st_size=65900, ...}) = 0 old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000 close(3) = 0 open("/lib/tls/libc.so.6", O_RDONLY) = 3 read(3,"\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200X\1"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000 old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0xa02000 old_mmap(0xb34000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0xb34000 old_mmap(0xb37000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb37000 close(3) = 0 set_thread_area({entry_number:-1 -> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 munmap(0xbf5ef000, 65900) = 0 fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000 read(0, 99 "99\n", 1024) = 3 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5fe000 write(1," 000000099\n", 10000000099 ) = 10 munmap(0xbf5fe000, 4096) = 0 exit_group(0) = ? |
从trace结构可以看到，系统首先调用execve开始一个新的进行，接着进行些环境的初始化操作，最后停顿在”read(0,”上面，这也就是执行到了我们的scanf函数，等待我们输入数字呢，在输入完99之后，在调用write函数将格式化后的数值”000000099″输出到屏幕，最后调用exit_group退出进行，完成整个程序的执行过程。
跟踪信号传递
我们还是使用上面的那个test程序，来观察进程接收信号的情况。还是先strace ./test，等到等待输入的画面的时候不要输入任何东西，然后打开另外一个窗口，输入如下的命令
| 1 | killall test |
这时候就能看到我们的程序推出了，最后的trace结果如下：
| 1 2 | oracle@orainst[orcl]:~ $strace ./test |
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 | execve("./test", ["./test"], [/* 41 vars */]) = 0 uname({sys="Linux", node="orainst.desktop.mycompany.com", ...}) = 0 brk(0) = 0x9ae2000 old_mmap(NULL, 65900, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5ef000 close(3) = 0 open("/lib/tls/libc.so.6", O_RDONLY) = 3 read(3,"\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\200X\1"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=1571692, ...}) = 0 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ee000 old_mmap(NULL, 1275340, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x2e9000 old_mmap(0x41b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x132000) = 0x41b000 old_mmap(0x41e000, 9676, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x41e000 close(3) = 0 set_thread_area({entry_number:-1 -> 6, base_addr:0xbf5ee740, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 munmap(0xbf5ef000, 65900) = 0 fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5ff000 read(0, 0xbf5ff000, 1024) = ? ERESTARTSYS (To be restarted) --- SIGTERM (Terminated) @ 0 (0) --- +++ killed by SIGTERM +++ |
trace中很清楚的告诉你test进程”+++ killed by SIGTERM +++”。
系统调用统计
strace不光能追踪系统调用，通过使用参数-c，它还能将进程所有的系统调用做一个统计分析给你，下面就来看看strace的统计，这次我们执行带-c参数的strace：
| 1 | strace -c ./test |
最后能得到这样的trace结果：
| 1 2 | oracle@orainst[orcl]:~ $strace -c ./test |
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | execve("./test", ["./test"], [/* 41 vars */]) = 0 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 45.90 0.000140 5 27 25 open 34.43 0.000105 4 24 21 stat64 7.54 0.000023 5 5 old_mmap 2.62 0.000008 8 1 munmap 1.97 0.000006 6 1 uname 1.97 0.000006 2 3 fstat64 1.64 0.000005 3 2 1 read 1.31 0.000004 2 2 close 0.98 0.000003 3 1 brk 0.98 0.000003 3 1 mmap2 0.66 0.000002 2 1 set_thread_area ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000305 68 47 total |
这里很清楚的告诉你调用了那些系统函数，调用次数多少，消耗了多少时间等等这些信息，这个对我们分析一个程序来说是非常有用的。
常用参数说明
除了-c参数之外，strace还提供了其他有用的参数给我们，让我们能很方便的得到自己想要的信息，下面就对那些常用的参数一一做个介绍。
重定向输出
参数-o用在将strace的结果输出到文件中，如果不指定-o参数的话，默认的输出设备是STDERR，也就是说使用”-o filename”和” 2>filename”的结果是一样的。
| 1 2 3 | # 这两个命令都是将strace结果输出到文件test.txt中 strace -c -o test.txt ./test strace -c ./test 2>test.txt |
对系统调用进行计时
strace可以使用参数-T将每个系统调用所花费的时间打印出来，每个调用的时间花销现在在调用行最右边的尖括号里面。
| 1 2 | oracle@orainst[orcl]:~ $strace -T ./test |
| 1 2 3 4 5 6 7 8 9 | // 这里只摘录部分结果 read(0, 1 "1\n", 1024) = 2 <2.673455> fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 <0.000014> mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xbf5fe000 <0.000017> write(1,"000000001\n", 10000000001 ) = 10 <0.000016> munmap(0xbf5fe000, 4096) = 0 <0.000020> exit_group(0) = ? |
系统调用的时间
这是一个很有用的功能，strace会将每次系统调用的发生时间记录下来，只要使用-t/tt/ttt三个参数就可以看到效果了，具体的例子可以自己去尝试。
| 参数名 | 输出样式 | 说明 |
|---|---|---|
| -t | 10:33:04 exit_group(0) | 输出结果精确到秒 |
| -tt | 10:33:48.159682 exit_group(0) | 输出结果精确到微妙 |
| -ttt | 1262169244.788478 exit_group(0) | 精确到微妙，而且时间表示为unix时间戳 |
截断输出
-s参数用于指定trace结果的每一行输出的字符串的长度，下面看看test程序中-s参数对结果有什么影响，现指定-s为20，然后在read的是是很我们输入一个超过20个字符的数字串
| 1 | strace -s 20 ./test |
| 1 2 | read(0, 2222222222222222222222222 // 我们输入的2一共有25个 "22222222222222222222"..., 1024) = 26 // 而我们看到的结果中2只有20个 |
trace一个现有的进程
strace不光能自己初始化一个进程进行trace，还能追踪现有的进程，参数-p就是取这个作用的，用法也很简单，具体如下。
| 1 | strace -p pid |
综合例子
说了那么多的功能和参数，现在我们来一个实用点的，就是研究下Oracle的lgwr进程，看看这个进程是不是像文档所说的那样没3s钟写一次log文件，考虑到lgwr写日志的触发条件比较多，我们需要找一个空闲的Oracle实例做这个实验。
我们先要得到lgwr进程的pid，运行下面的命令
| 1 | ps -ef|grep lgwr |
| 1 | oracle 5912 1 0 Nov12 ? 00:14:56 ora_lgwr_orcl |
得到lgwr的pid是5912，现在启动strace，然后将trace的几个输出到lgwr.txt文件中，执行下面的命令
| 1 | strace -tt -s 10 -o lgwr.txt -p 5912 |
过一会之后停止strace，然后查看结果。由于输出的结果比较多，为了方便我们只看Oracle写入log文件时用的pwrite函数的调用
| 1 | grep 'pwrite\(20' lgwr.txt |
等等，为什么grep的时候用的是”pwrite(2″呢？，因为我知道我这个机器打开的当前的log文件的句柄编号都是2开始的。具体查找方法是先使用下面的语句找出当前活动的日志文件都有哪些：
| 1 2 | select member, v$log.status from v$log, v$logfile where v$log.group#=v$logfile.group#; |
得到
| 1 2 3 4 5 6 7 8 9 10 | MEMBER STATUS -------------------------------------------------- ---------------- /db/databases/orcl/redo-01-a/redo-t01-g03-m1.log INACTIVE /db/databases/orcl/redo-03-a/redo-t01-g03-m2.log INACTIVE /db/databases/orcl/redo-02-a/redo-t01-g02-m1.log CURRENT /db/databases/orcl/redo-04-a/redo-t01-g02-m2.log CURRENT /db/databases/orcl/redo-01-a/redo-t01-g01-m1.log INACTIVE /db/databases/orcl/redo-03-a/redo-t01-g01-m2.log INACTIVE /db/databases/orcl/redo-02-a/redo-t01-g04-m1.log INACTIVE /db/databases/orcl/redo-04-a/redo-t01-g04-m2.log INACTIVE |
然后到/proc中去找打开文件的句柄：
| 1 | ll/proc/.5912/fd/ |
得到
| 1 2 3 4 5 6 7 8 | lrwx------ 1 oracle dba 64 Dec 30 10:55 18 ->/db/databases/orcl/redo-01-a/redo-t01-g01-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 19 ->/db/databases/orcl/redo-03-a/redo-t01-g01-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 20 ->/db/databases/orcl/redo-02-a/redo-t01-g02-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 21 ->/db/databases/orcl/redo-04-a/redo-t01-g02-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 22 ->/db/databases/orcl/redo-01-a/redo-t01-g03-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 23 ->/db/databases/orcl/redo-03-a/redo-t01-g03-m2.log lrwx------ 1 oracle dba 64 Dec 30 10:55 24 ->/db/databases/orcl/redo-02-a/redo-t01-g04-m1.log lrwx------ 1 oracle dba 64 Dec 30 10:55 25 ->/db/databases/orcl/redo-04-a/redo-t01-g04-m2.log |
现在能看到我机器当前日志文件的句柄分别是20和21。
现在我们得到如下结果
| 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 | 11:13:55.603245 pwrite(20,"\1\"\0\0J!"..., 1536, 4363264) = 1536 11:13:55.603569 pwrite(21,"\1\"\0\0J!"..., 1536, 4363264) = 1536 11:13:55.606888 pwrite(20,"\1\"\0\0M!"..., 1536, 4364800) = 1536 11:13:55.607172 pwrite(21,"\1\"\0\0M!"..., 1536, 4364800) = 1536 11:13:55.607934 pwrite(20,"\1\"\0\0P!"..., 1536, 4366336) = 1536 11:13:55.608199 pwrite(21,"\1\"\0\0P!"..., 1536, 4366336) = 1536 11:13:55.610260 pwrite(20,"\1\"\0\0S!"..., 1536, 4367872) = 1536 11:13:55.610530 pwrite(21,"\1\"\0\0S!"..., 1536, 4367872) = 1536 11:14:00.602446 pwrite(20,"\1\"\0\0V!"..., 1536, 4369408) = 1536 11:14:00.602750 pwrite(21,"\1\"\0\0V!"..., 1536, 4369408) = 1536 11:14:00.606386 pwrite(20,"\1\"\0\0Y!"..., 1536, 4370944) = 1536 11:14:00.606676 pwrite(21,"\1\"\0\0Y!"..., 1536, 4370944) = 1536 11:14:00.607900 pwrite(20,"\1\"\0\0\\"..., 1024, 4372480) = 1024 11:14:00.608161 pwrite(21,"\1\"\0\0\\"..., 1024, 4372480) = 1024 11:14:00.608816 pwrite(20,"\1\"\0\0^!"..., 1024, 4373504) = 1024 11:14:00.609071 pwrite(21,"\1\"\0\0^!"..., 1024, 4373504) = 1024 11:14:00.611142 pwrite(20,"\1\"\0\0`!"..., 1536, 4374528) = 1536 11:14:00.611454 pwrite(21,"\1\"\0\0`!"..., 1536, 4374528) = 1536 11:14:05.602804 pwrite(20,"\1\"\0\0c!"..., 1024, 4376064) = 1024 11:14:05.603119 pwrite(21,"\1\"\0\0c!"..., 1024, 4376064) = 1024 11:14:05.607731 pwrite(20,"\1\"\0\0e!"..., 1024, 4377088) = 1024 11:14:05.608020 pwrite(21,"\1\"\0\0e!"..., 1024, 4377088) = 1024 11:14:05.608690 pwrite(20,"\1\"\0\0g!"..., 1024, 4378112) = 1024 11:14:05.608962 pwrite(21,"\1\"\0\0g!"..., 1024, 4378112) = 1024 11:14:05.611022 pwrite(20,"\1\"\0\0i!"..., 1536, 4379136) = 1536 11:14:05.611283 pwrite(21,"\1\"\0\0i!"..., 1536, 4379136) = 1536 |
很遗憾的是我们看到的写日志文件的操作是每5s进行一次，可能是因为这个系统空闲的原因？这个还需要再研究一下。
延伸阅读
- Introducing strace
- Linux随机数发生器导致Apache进程全部Block的问题追查
相关 [linux strace 系统调用] 推荐：
Linux 中用 strace 追踪系统调用和信号值
- - 博客园_iTech's Blog原文地址： http://www.dbabeta.com/2009/strace.html. 打开man strace，我们能看到对strace的最简洁的介绍就是”strace – trace system calls and signals”. 实际上strace是一个集诊断、调试、统计与一体的工具，我们可以使用strace对应用的系统调用和信号传递的跟踪结果来对应用进行分析，以达到解决问题或者是了解应用工作过程的目的.
linux文件操作之系统调用
- L - 博客园-首页原创精华区 在linux中，一切都是文件，文件为操作系统服务和设备提供了一个简单而统一的接口，这就意味者程序可以像使用文件那样使用各种设备. 大多数情况下对于文件的操作只用到open，write，lseek，read，close五个系统调用. 本文通过一个简单的例子来介绍这五个调用及关联内容. 这是一个简单的读写文件的例子，先创建一个文本文件，写入一些内容，再把文本内容输出到标准输出，下面开始分析这个例子：.
Linux系统调用过程分析
- - CSDN博客架构设计推荐文章《Linux内核设计与实现》. linux的系统调用过程：. 用户程序------>C库（即API）：INT 0x80 ----->system_call------->系统调用服务例程-------->内核程序. 先说明一下，我们常说的用户API其实就是系统提供的C库. 系统调用是通过软中断指令 INT 0x80 实现的，而这条INT 0x80指令就被封装在C库的函数中.
strace命令小结
- - jackyrongstrace命令是很有用的进程跟踪命令，下面小结下：. 1 strace 是一个非常简单的工具，用来跟踪可执行程序的系统调用(system call). 最简单的使用是，它追踪可行程序运行时的整个生命周期，输出每一个系统调用的名字，参数和返回值. 但是它还可以做更多的事情：. 它可以基于系统调用或者系统调用组来过滤.
[译]strace的10个命令
- - 鸟窝strace是一个在类Unix操作系统如Linux上做debugging和trouble shooting的超级好用的工具. 它可以捕获和记录进程的所有系统调用，以及这个进程接收的所有信号. 原文: 10 Strace Commands for Troubleshooting and Debugging Linux Processes.
通过Strace定位故障原因
- - 火丁笔记俗话说：不怕贼偷，就怕贼惦记着. 在面对故障的时候，我也有类似的感觉：不怕出故障，就怕你不知道故障的原因，眼睁睁地看着情况恶化却束手无策. 十一长假还没结束，服务器却频现高负载，Nginx出现错误日志：. 看上去是Upstream出了问题，在本例中Upstream就是PHP. 一开始我搞不清楚到底是哪个PHP脚本出现了问题，无奈之下只好通过不断重启PHP服务来缓解高负载故障.
手把手教你用Strace诊断问题
- - 火丁笔记早些年，如果你知道有个 strace 命令，就很牛了，而现在大家基本都知道 strace 了，如果你遇到性能问题求助别人，十有八九会建议你用 strace 挂上去看看，不过当你挂上去了，看着满屏翻滚的字符，却十有八九看不出个所以然. 本文通过一个简单的案例，向你展示一下在用 strace 诊断问题时的一些套路.
分布式系统调用链监控
- - IT瘾-geek应用架构由集中式向分布式演进后，整个调用关系变得复杂. 分布式架构由复杂且较大规模集群构成，各个应用之间相当独立，可能由不同团队、不同语言实现. 系统一个完整的调用过程可能横跨多个服务及数据中心. 复杂的调用导致系统出问题后难以定位问题. 无法准确知道整体系统性能及运行情况. 一个请求完整的调用链可能如下图，经过多个系统服务，调用关系复杂.