Linux 中用 strace 追踪系统调用和信号值

时间 2020-05-13 标签 linux 中用 strace 追踪系统调用信号值

原文地址：http://www.dbabeta.com/2009/strace.htmlhtml

什么是stracenode

打开man strace，咱们能看到对strace的最简洁的介绍就是”strace – trace system calls and signals”。实际上strace是一个集诊断、调试、统计与一体的工具，咱们可使用strace对应用的系统调用和信号传递的跟踪结果来对应用进行分析，以达到解决问题或者是了解应用工做过程的目的。固然strace与专业的调试工具好比说gdb之类的是无法相比的，由于它不是一个专业的调试器。linux

strace的最简单的用法就是执行一个指定的命令，在指定的命令结束以后它也就退出了。在命令执行的过程当中，strace会记录和解析命令进程的全部系统调用以及这个进程所接收到的全部的信号值。oracle

命令的使用方法以下ide

strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ...

[ -ofile ] [-ppid ] ... [ -sstrsize ] [ -uusername ]

[ -Evar=val ] ... [ -Evar ]...

[command[ arg ... ] ]

strace -c [ -eexpr ] ... [ -Ooverhead ] [ -Ssortby ]

[command[ arg... ] ]

strace的基本用法

追踪系统调用

如今咱们作一个很简单的程序来演示strace的基本用法。这个程序的C语言代码以下：函数

# 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，最后获得以下的结果：post

1 2	//直接执行test的结果 oracle@orainst[orcl]:~ $./test

// 执行的结果

000000099

1 2	//经过strace执行test的结果 oracle@orainst[orcl]:~ $strace ./test

// 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退出进行，完成整个程序的执行过程。spa

跟踪信号传递

咱们仍是使用上面的那个test程序，来观察进程接收信号的状况。仍是先strace ./test，等到等待输入的画面的时候不要输入任何东西，而后打开另一个窗口，输入以下的命令.net

1	killall test

这时候就能看到咱们的程序推出了，最后的trace结果以下：

1 2	oracle@orainst[orcl]:~ $strace ./test

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

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”的结果是同样的。

# 这两个命令都是将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

// 这里只摘录部分结果

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#;

获得

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/

获得

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。

如今咱们获得以下结果

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进行一次，多是由于这个系统空闲的缘由？这个还须要再研究一下。

Linux 中用 strace 追踪系统调用和信号值

strace的基本用法

追踪系统调用

跟踪信号传递

系统调用统计

经常使用参数说明

重定向输出

对系统调用进行计时

系统调用的时间

截断输出

trace一个现有的进程

综合例子

延伸阅读