五种利用strace查故障的简单方法

什么是strace?

strace是一个非常简单的工具，它可以跟踪系统调用的执行。最简单的方式，它可以从头到尾跟踪binary的执行，然后以一行文本输出系统调用的名字，参数和返回值。

其实它可以做的更多：

可以对特定的系统调用或者几组系统调用进行过滤

可以通过统计特定系统调用的调用次数、耗费的时间、成功和失败的次数来配置(profile)系统调用的使用I

跟踪发送给进程的信号量

可以通过pid附着(attach)到任何运行的进程

如果你使用的是其它Unix系统，它类似于"truss"。其它更复杂的是Sun的Dtrace.

怎么使用它 1) 找出程序在startup的时候读取的哪个config文件？

有没有尝过解决为什么某些程序不读去你认为它应该读取的config文件的问题？

strace php 2>&1 | grep php.ini

open( "/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)

open( "/usr/local/lib/php.ini", O_RDONLY) = 4

lstat64( "/usr/local/lib/php.ini", {st_mode=S_IFLNK|0777, st_size=27, ...}) = 0

readlink( "/usr/local/lib/php.ini", "/usr/local/Zend/etc/php.ini", 4096) = 27

lstat64( "/usr/local/Zend/etc/php.ini", {st_mode=S_IFREG|0664, st_size=40971, ...}) = 0

可以看出这个版本的PHP从/usr/local/lib/php.init读取config文件（但是先尝试/usr/locl/bin)

如果只关心特定的系统调用，有更精致的方法

$ strace -e open php 2>&1 | grep php.ini

open( "/usr/local/bin/php.ini", O_RDONLY) = -1 ENOENT (No such file or directory)

open( "/usr/local/lib/php.ini", O_RDONLY) = 4

相同的方法适用于很多其它类似的问题。比如说，安装了不同版本的library，不确定实际上加载了哪一个版本。

-e expr -- a qualifying expression: option=[!]all or option=[!]val1[,val2]...
options: trace, abbrev, verbose, raw, signal, read, write

2) 为什么这个程序没有打开我的文件？

是否曾经碰到过一个程序拒绝读取它没有权限的文件，但是你发誓原因是它没有真正找到那个文件？对程序跟踪open,access调用，注意失败的情况

$ strace -e open,access 2>&1 | grep your-filename

3) 某个进程现在在做什么?

某个进程突然占用了很多CPU? 或者某个进程看起来像hanging了？

找到对应的pid，然后

hang:

悬挂,挂起的意思
就是一个进程被暂时停止执行.

root@dev:~# strace -p 15427

Process 15427 attached - interrupt to quit

futex(0x402f4900, FUTEX_WAIT, 2, NULL

Process 15427 detached

嗯，这个例子里面，它在调用futex()的时候挂起了。

"strace -p"非常有用，它减少了很多猜测工作，也不需要重新启动应用。

-p pid -- trace process with process id PID, may be repeated

4) 是谁偷走了时间？

你可以重新编译app，打开profiling，以获取精确的信息。但是通常利用strace附着(attach）一个进程以快速地看一下当前时间花费在哪里非常有用。可以看下是否90%的CPU用在真正的工作，或者用在其它方面了。

root@dev:~# strace -c -p 11084

Process 11084 attached - interrupt to quit

Process 11084 detached

% time seconds usecs/call calls errors syscall

------ ----------- ----------- --------- --------- ----------------

94.59 0.001014 48 21 select

2.89 0.000031 1 21 getppid

2.52 0.000027 1 21 time

------ ----------- ----------- --------- --------- ----------------

100.00 0.001072 63 total

root@dev:~#

-c -- count time, calls, and errors for each syscall and report summary
-C -- like -c but also print regular output

在执行strace -c -p命令以后，等到你关注的时间到了后，按ctrl-c退出，strace会列出如上的profiling数据。

在这个例子中，程序花了绝大部分时间在等待select()。它在每一个slect()调用这件调用getpid()和time()，这是一种典型的事件循环。

你也可以运行"start to finish"，这里是"ls"

root@dev:~# strace -c >/dev/null ls

% time seconds usecs/call calls errors syscall

------ ----------- ----------- --------- --------- ----------------

23.62 0.000205 103 2 getdents64

18.78 0.000163 15 11 1 open

15.09 0.000131 19 7 read

12.79 0.000111 7 16 old_mmap

7.03 0.000061 6 11 close

4.84 0.000042 11 4 munmap

4.84 0.000042 11 4 mmap2

4.03 0.000035 6 6 6 access

3.80 0.000033 3 11 fstat64

1.38 0.000012 3 4 brk

0.92 0.000008 3 3 3 ioctl

0.69 0.000006 6 1 uname

0.58 0.000005 5 1 set_thread_area

0.35 0.000003 3 1 write

0.35 0.000003 3 1 rt_sigaction

0.35 0.000003 3 1 fcntl64

0.23 0.000002 2 1 getrlimit

0.23 0.000002 2 1 set_tid_address

0.12 0.000001 1 1 rt_sigprocmask

------ ----------- ----------- --------- --------- ----------------

100.00 0.000868 87 10 total

正如你的预期，它耗费了大部分时间在两次调用来读取目录条目上（因为运行于一个小的目录上，所有只有两次） 5) 为什么无法连接到服务器?

调试进程无法连接到远端服务器有时候是件非常头痛的事。DNS会失败，connect会挂起，server有可能返回一些意料之外的数据。可以使用tcpdump来分析这些情况，它是一个非常棒的工作。但是有时候你strace可以给你更简单，耿直借的角度，因为strace只返回你的进程相关的系统调用产生的数据。如果你要从100个连接到统一个数据服务器的运行进程里面找出一个连接所做的事情，用strace就比tcpdump简单得多。

下面是跟踪"nc"连接到 80端口的例子

$ strace -e poll,select,connect,recvfrom,sendto nc 80

sendto(3, "\\24\\0\\0\\0\\26\\0\\1\\3\\255\\373NH\\0\\0\\0\\0\\0\\0\\0\\0", 20, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20

connect(3, {sa_family=AF_FILE, path= "/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "\\213\\321\\1\\0\\0\\1\\0\\0\\0\\0\\0\\0\\3www\\4news\\3com\\0\\0\\34\\0\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "\\213\\321\\201\\200\\0\\1\\0\\1\\0\\1\\0\\0\\3www\\4news\\3com\\0\\0\\34\\0\\1\\300\\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, [16]) = 153

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "k\\374\\1\\0\\0\\1\\0\\0\\0\\0\\0\\0\\3www\\4news\\3com\\0\\0\\1\\0\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "k\\374\\201\\200\\0\\1\\0\\2\\0\\0\\0\\0\\3www\\4news\\3com\\0\\0\\1\\0\\1\\300\\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, [16]) = 106

connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, 28) = 0

poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1

sendto(3, "\\\\\\2\\1\\0\\0\\1\\0\\0\\0\\0\\0\\0\\3www\\4news\\3com\\0\\0\\1\\0\\1", 30, MSG_NOSIGNAL, NULL, 0) = 30

poll([{fd=3, events=POLLIN, revents=POLLIN}], 1, 5000) = 1

recvfrom(3, "\\\\\\2\\201\\200\\0\\1\\0\\2\\0\\0\\0\\0\\3www\\4news\\3com\\0\\0\\1\\0\\1\\300\\f"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr( "62.30.112.39")}, [16]) = 106

connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr( "216.239.122.102")}, 16) = -1 EINPROGRESS (Operation now in progress)

select(4, NULL, [3], NULL, NULL) = 1 (out [3])

发生了什么？

注意到尝试连接/var/run/nscd/socket?这意味着nc首先尝试连接NSCD--the Name Service Cache Daemon--它通常用来基于NIS,YP,LDAP或者类似的目录协议提供域名查询。在这里它失败了。

然后它连接DNS （DNS是port 53,所以"sin_port=htons(53)")。然后它调用了"sendto（）“,发送包含的DNS 包。然后读回响应。不知为何，它尝试了三次，最后一次有细微的却别，我猜是它十一个CNAME（别名），多次请求可能是nc故意的。

最后，它发起一个connect()请求到得到的IP地址，注意到返回值是EINPROGRESS。这意味这connect是非阻塞的，nc希望继续处理，然后它调用slect()，连接建立后，select返回成功。

添加"read","write"到过滤系统调用列表中，连接时输入一个字串，可能会得到如下

Notice the connection attempts to /var/run/nscd/socket? They mean nc first tries to connect to NSCD - the Name Service Cache Daemon - which is usually used in setups that rely on NIS, YP, LDAP or similar directory protocols for name lookups. In this case the connects fails.

It then moves on to DNS (DNS is port 53, hence the "sin_port=htons(53)" in the following connect. You can see it then does a "sendto()" call, sending a DNS packet that contains . It then reads back a packet. For whatever reason it tries three times, the last with a slightly different request. My best guess why in this case is that is a CNAME (an "alias"), and the multiple requests may just be an artifact of how nc deals with that.

Then in the end, it finally issues a connect() to the IP it found. Notice it returns EINPROGRESS. That means the connect was non-blocking - nc wants to go on processing. It then calls select(), which succeeds when the connection was successful.

Try adding "read" and "write" to the list of syscalls given to strace and enter a string when connected, and you'll get something like this:

write(3, "test\\n", 5) = 5

poll([{fd=3, events=POLLIN, revents=POLLIN}, {fd=0, events=POLLIN}], 2, -1) = 1

read(3, "

这表示从标准输入读入"test"+换行符，并写到网络连接中，然后调用poll等待响应，读取响应，写回标准输出。

一切看起来都正常工作。

原文地址：

早些年，如果你知道有个 strace 命令，就很牛了，而现在大家基本都知道 strace 了，如果你遇到性能问题求助别人，十有八九会建议你用 strace 挂上去看看，不过当你挂上去了，看着满屏翻滚的字符，却十有八九看不出个所以然。本文通过一个简单的案例，向你展示一下在用 strace 诊断问题时的一些套路。

如下真实案例，如有雷同，实属必然！让我们看一台高负载服务器的 top 结果：

技巧：运行 top 时，按「1」打开 CPU 列表，按「shift+p」以 CPU 排序。

在本例中大家很容易发现 CPU 主要是被若干个 PHP 进程占用了，同时 PHP 进程占用的比较多的内存，不过系统内存尚有结余，SWAP 也不严重，这并不是问题主因。

不过在 CPU 列表中能看到 CPU 主要消耗在内核态「sy」，而不是用户态「us」，和我们的经验不符。Linux 操作系统有很多用来跟踪程序行为的工具，内核态的函数调用跟踪用「strace」，用户态的函数调用跟踪用「ltrace」，所以这里我们应该用「strace」：

很明显，一个 clone 操作需要几百毫秒，至于 clone 的含义，参考 man 文档：

clone() creates a new process, in a manner similar to fork(2). It is actually a library function layered on top of the underlying clone() system call, hereinafter referred to as sys_clone. A description of sys_clone is given towards the end of this page.

Unlike fork(2), these calls allow the child process to share parts of its execution context with the calling process, such as the memory space, the table of file descriptors, and the table of signal handlers. (Note that on this manual page, “calling process” normally corresponds to “parent process”. But see the description of CLONE_PARENT below.)

简单来说，就是创建一个新进程。那么在 PHP 里什么时候会出现此类系统调用呢？查询业务代码看到了 exec 函数，通过如下命令验证它确实会导致 clone 系统调用：

strace -f -e trace=read,write -p 17151 -o log #跟踪进程17151及子进程中read和write系统调用，输出到log文件.

-e expr 
指定一个表达式,用来控制如何跟踪.格式如下: 
[qualifier=][!]value1[,value2]... 
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用来限定的符号或数字.默认的 qualifier是 trace.感叹号是否定符号.例如: 
-eopen等价于 -e trace=open,表示只跟踪open调用.而-etrace!=open表示跟踪除了open以外的其他调用.有两个特殊的符号 all 和 none. 
注意有些shell使用!来执行历史记录里的命令,所以要使用\\. l. 
-e trace=file 
只跟踪有关文件操作的系统调用. 
-e trace=process 
只跟踪有关进程控制的系统调用. 
-e trace=network 
跟踪与网络有关的所有系统调用. 
-e strace=signal 
跟踪所有与系统信号有关的 系统调用 
-e trace=ipc 
跟踪所有与进程通讯有关的系统调用 
-e abbrev= 
设定 strace输出的系统调用的结果集.-v 等与 abbrev=none.默认为abbrev=all. 
-e raw= 
将指 定的系统调用的参数以十六进制显示. 
-e signal= 
指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号. 
-e read= 
输出从指定文件中读出 的数据.例如: 
-e read=, 
-e write=

通用的完整用法：

strace -o output.txt -T -tt -e trace=all -p 28979

上面的含义是跟踪28979进程的所有系统调用（-e trace=all），并统计系统调用的花费时间，以及开始时间（并以可视化的时分秒格式显示），最后将记录结果存在output.txt文件里面。

strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ... [ -ofile ] [-ppid ] ... [ -sstrsize ] [ -uusername ] [ -Evar=val ] ... [ -Evar ]... [ command [ arg ... ] ]

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

strace是什么？

按照strace官网的描述, strace是一个可用于诊断、调试和教学的Linux用户空间跟踪器。我们用它来监控用户空间进程和内核的交互，比如系统调用、信号传递、进程状态变更等。

strace底层使用内核的ptrace特性来实现其功能。

在运维的日常工作中，故障处理和问题诊断是个主要的内容，也是必备的技能。strace作为一种动态跟踪工具，能够帮助运维高效地定位进程和服务故障。它像是一个侦探，通过系统调用的蛛丝马迹，告诉你异常的真相。

strace能做什么？

运维工程师都是实践派的人，我们还是先来个例子吧。

我们从别的机器copy了个叫做some_server的软件包过来，开发说直接启动就行，啥都不用改。可是尝试启动时却报错，根本起不来！

启动命令：

./some_server ../conf/some_server.conf输出:

FATAL: InitLogFile failed iRet: -1!

Init error: -1655为什么起不来呢？从日志看，似乎是初始化日志文件失败，真相到底怎样呢？我们用strace来看看。

strace -tt -f ./some_server ../conf/some_server.conf输出:

我们注意到，在输出InitLogFile failed错误的前一行，有个open系统调用:

23:14:24.448034 open("/usr/local/apps/some_server/log//server_agent.log", O_RDWR|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = -1 ENOENT (No such file or directory)它尝试打开文件/usr/local/apps/some_server/log//server_agent.log来写(不存在则创建)，可是却出错了，返回码是-1, 系统错误号errorno为ENOENT。查下open系统调用的手册页：

man 2 open

搜索ENOENT这个错误号errno的解释

ENOENT O_CREAT is not set and the named file does not exist. Or, a directory component in pathname does not exist or is a dangling symbolic link.

这里说得比较清楚，因为我们例子中的open选项指定了O_CREAT选项，这里errno为ENOENT的原因是日志路径中某个部分不存在或者是一个失效的符号链接。我们来一级一级看下路径中的哪部分不存在：

ls -l /usr/local/apps/some_server/log

ls: cannot access /usr/local/apps/some_server/log: No such file or directory

ls -l /usr/local/apps/some_server

total 8

drwxr-xr-x 2 root users 4096 May 14 23:13 bin

drwxr-xr-x 2 root users 4096 May 14 22:48 conf原来是log子目录不存在！上层目录都是存在的。手工创建log子目录后，服务就能正常启动了。

回过头来， strace究竟能做什么呢？

它能够打开应用进程的这个黑盒，通过系统调用的线索，告诉你进程大概在干嘛。

strace怎么用？

既然strace是用来跟踪用户空间进程的系统调用和信号的，在进入strace使用的主题之前，我们的先理解什么是系统调用。

关于系统调用：

按维基百科中的解释，在计算机中，系统调用（英语：system call），又称为系统呼叫，指运行在用户空间的程序向操作系统内核请求需要更高权限运行的服务。

系统调用提供用户程序与操作系统之间的接口。操作系统的进程空间分为用户空间和内核空间：

操作系统内核直接运行在硬件上，提供设备管理、内存管理、任务调度等功能。

用户空间通过API请求内核空间的服务来完成其功能——内核提供给用户空间的这些API, 就是系统调用。

在Linux系统上，应用代码通过glibc库封装的函数，间接使用系统调用。

Linux内核目前有300多个系统调用，详细的列表可以通过syscalls手册页查看。这些系统调用主要分为几类：

文件和设备访问类比如open/close/read/write/chmod等

进程管理类 fork/clone/execve/exit/getpid等

信号类 signal/sigaction/kill 等

内存管理 brk/mmap/mlock等

进程间通信IPC shmget/semget * 信号量，共享内存，消息队列等

网络通信 socket/connect/sendto/sendmsg 等

其他熟悉Linux系统调用/系统编程，能够让我们在使用strace时得心应手。不过，对于运维的问题定位来说，知道strace这个工具，会查系统调用手册，就差不多够了。

想要深入了解的同学，建议阅读《Linux系统编程》, 《Unix环境高级编程》等书籍。

我们回到strace的使用上来。strace有两种运行模式。

一种是通过它启动要跟踪的进程。用法很简单，在原本的命令前加上strace即可。比如我们要跟踪 "ls -lh /var/log/messages" 这个命令的执行，可以这样：

strace ls -lh /var/log/messages另外一种运行模式，是跟踪已经在运行的进程，在不中断进程执行的情况下，理解它在干嘛。这种情况，给strace传递个-p pid 选项即可。

比如，有个在运行的some_server服务，第一步，查看pid:

pidof some_server

17553得到其pid 17553然后就可以用strace跟踪其执行:

strace -p 17553完成跟踪时，按ctrl + C 结束strace即可。

strace有一些选项可以调整其行为，我们这里介绍下其中几个比较常用的，然后通过示例讲解其实际应用效果。

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部分输出:

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

strace -o strace.log -tt -p 24298查看strace.log, 我们在最后2行看到如下内容:

22:47:42.803937 wait4(-1,

22:47:43.228422 +++ killed by SIGKILL +++这里可以看出，进程是被其他进程用KILL信号杀死的。

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

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

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

#include

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, 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即可。但有时候我们要跟踪一类系统调用，比如所有和文件名有关的调用、所有和内存分配有关的调用。

如果人工输入每一个具体的系统调用名称，可能容易遗漏。于是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等

绝大多数情况，我们使用上面的组合名字就够了。实在需要跟踪具体的系统调用时，可能需要注意C库实现的差异。

比如我们知道创建进程使用的是fork系统调用，但在glibc里面，fork的调用实际上映射到了更底层的clone系统调用。使用strace时，得指定-e trace=clone, 指定-e trace=fork什么也匹配不上。

3、性能分析

假如有个需求，统计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 ))

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个进程！

而进程创建和销毁的代价是相当高的，性能不差才怪。

当发现进程或服务异常时，我们可以通过strace来跟踪其系统调用，“看看它在干啥”，进而找到异常的原因。熟悉常用系统调用，能够更好地理解和使用strace。

当然，万能的strace也不是真正的万能。当目标进程卡死在用户态时，strace就没有输出了。

这个时候我们需要其他的跟踪手段，比如gdb/perf/SystemTap等。

使用Linux Strace跟踪调试Oracle程序进程

所谓操作系统，是应用程序与服务器硬件进行沟通的中间层。应用程序的所有操作，都是和操作系统进行沟通交互。操作系统负责将所有交互转化为设备语言，进行硬件交互。我们在进行 Oracle 故障调试和内核原理工作的时候，经常需要了解后台运行的动作和细节。一些故障场景，如程序进程住、无法登陆等问题，就需要操作系统级别监控，检查定位问题。 Oracle 自身已经提供了很多这类型的工具，如 oradebug 、各种等待事件和跟踪方式。此外，各类型的操作系统提供出很多系统级别工具，帮助我们进行监控。本篇主要介绍 Linux strace 工具典型使用方法，留待需要朋友待查。 14:21:14 execve("/u01/app/oracle/bin/sqlplus", ["sqlplus", "/nolog"], [/* 31 vars */]) = 0 14:21:14 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) 14:21:14 open("/u01/app/oracle/lib/tls/x86_64/libsqlplus.so", O_RDONLY) = -1 ENOENT (No such file or directory) 14:21:14 stat("/u01/app/oracle/lib/tls/x86_64", 0x7fff3076da50) = -1 ENOENT (No such file or directory) 14:21:14 open("/u01/app/oracle/lib/tls/libsqlplus.so", O_RDONLY) = -1 ENOENT (No such file or directory) 14:21:14 stat("/u01/app/oracle/lib/tls", 0x7fff3076da50) = -1 ENOENT (No such file or directory) 14:21:14 open("/u01/app/oracle/lib/x86_64/libsqlplus.so", O_RDONLY) = -1 ENOENT (No such file or directory) 14:21:14 stat("/u01/app/oracle/lib/x86_64", 0x7fff3076da50) = -1 ENOENT (No such file or directory) 14:21:14 open("/u01/app/oracle/lib/libsqlplus.so", O_RDONLY) = 3 14:21:14 open("/u01/app/oracle/lib/libclntsh.so.11.1", O_RDONLY) = 3 14:21:14 open("/u01/app/oracle/lib/libnnz11.so", O_RDONLY) = 3 14:21:14 open("/u01/app/oracle/lib/libdl.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) （篇幅原因，有省略 14:21:14 access("/etc/tnsnav.ora", F_OK) = -1 ENOENT (No such file or directory) 14:21:14 access("/u01/app/oracle/network/admin/tnsnav.ora", F_OK) = -1 ENOENT (No such file or directory) 14:21:14 open("/u01/app/oracle/oracore/zoneinfo", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6 14:21:14 open("/u01/app/oracle/oracore/zoneinfo/timezlrg_1.dat", O_RDONLY) = 7 14:21:14 open("/u01/app/oracle/oracore/zoneinfo/timezlrg_2.dat", O_RDONLY) = 7 （读取各种时区数据 14:21:14 open("/u01/app/oracle/oracore/zoneinfo/timezone_14.dat", O_RDONLY) = 7 14:21:14 open("/u01/app/oracle/oracore/zoneinfo/timezlrg_14.dat", O_RDONLY) = 6 14:21:14 open("/usr/lib64/libnuma.so", O_RDONLY) = -1 ENOENT (No such file or directory) 14:21:14 open("/usr/lib64/libnuma.so.1", O_RDONLY) = 6 14:21:14 open("/proc/self/status", O_RDONLY) = 6 14:21:14 open("/sys/devices/system/node", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6 14:21:14 open("/sys/devices/system/node/node0/meminfo", O_RDONLY) = 7 14:21:14 open("/sys/devices/system/cpu", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6 14:21:14 open("/proc/self/status", O_RDONLY) = 6 14:21:14 open("/proc/sys/kernel/shmmax", O_RDONLY) = 6 14:21:14 open("/proc/meminfo", O_RDONLY) = 6 14:21:14 open("/usr/lib64/libnuma.so", O_RDONLY) = -1 ENOENT (No such file or directory) 14:21:14 open("/etc/localtime", O_RDONLY) = 6 14:21:14 open("/u01/app/oracle/rdbms/mesg/ocius.msb", O_RDONLY) = 6 14:21:14 stat("/u01/app/oracle/sqlplus/admin/glogin.sql", {st_mode=S_IFREG|0644, st_size=368, ...}) = 0 14:21:14 access("/u01/app/oracle/sqlplus/admin/glogin.sql", F_OK) = 0 14:21:14 statfs("/u01/app/oracle/sqlplus/admin/glogin.sql", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=174170552, f_bfree=147038320, f_bavail=138190973, f_files=44236800, f_ffree=44019067, f_fsid={1821877354, 763674030}, f_namelen=255, f_frsize=4096}) = 0 14:21:14 open("/u01/app/oracle/sqlplus/admin/glogin.sql", O_RDONLY) = 7 14:29:30 execve("/u01/app/oracle/bin/sqlplus", ["sqlplus", "/", "as", "sysdba"], [/* 31 vars */]) = 0 （相同篇幅内容，略 14:29:30 open("/u01/app/oracle/dbs/cm_xxxdb.dat", O_RDONLY|O_DSYNC) = -1 ENOENT (No such file or directory) 14:29:30 getcwd("/home/oracle", 256) = 13 14:29:30 open("/proc/self/cmdline", O_RDONLY) = 7 14:29:30 open("/etc/nsswitch.conf", O_RDONLY) = 7 14:29:30 open("/u01/app/oracle/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory) 14:29:30 open("/etc/ld.so.cache", O_RDONLY) = 7 14:29:30 open("/lib64/libnss_files.so.2", O_RDONLY) = 7 14:29:30 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 14:29:30 open("/u01/app/oracle/lib/libnque11.so", O_RDONLY) = 7 14:29:30 getcwd("/home/oracle", 256) = 13 14:29:30 open("/u01/app/oracle/nls/data/lx20369.nlb", O_RDONLY) = 7 14:29:30 open("/u01/app/oracle/nls/data/lx207d0.nlb", O_RDONLY) = 7 14:29:30 readlink("/proc/self/fd/0", "/dev/pts/0", 254) = 10 14:29:30 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 7 14:29:30 open("/etc/host.conf", O_RDONLY) = 7 14:29:30 open("/etc/resolv.conf", O_RDONLY) = 7 14:29:30 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 7 14:29:30 open("/etc/hostid", O_RDONLY) = -1 ENOENT (No such file or directory) 14:29:30 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 7 14:29:30 open("/u01/app/oracle/rdbms/mesg/oraus.msb", O_RDONLY) = 7 14:29:30 stat("/u01/app/oracle/sqlplus/admin/glogin.sql", {st_mode=S_IFREG|0644, st_size=368, ...}) = 0 14:29:30 access("/u01/app/oracle/sqlplus/admin/glogin.sql", F_OK) = 0 14:29:30 statfs("/u01/app/oracle/sqlplus/admin/glogin.sql", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=174170552, f_bfree=147038317, f_bavail=138190970, f_files=44236800, f_ffree=44019066, f_fsid={1821877354, 763674030}, f_namelen=255, f_frsize=4096}) = 0 14:29:30 open("/u01/app/oracle/sqlplus/admin/glogin.sql", O_RDONLY) = 7 17:36:42 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608271 17:36:42 semtimedop(6062085, {{16, -1, 0}}, 1, {1, 840000000}) = -1 EAGAIN (Resource temporarily unavailable) 17:36:44 getrusage(RUSAGE_SELF, {ru_utime={125, 122978}, ru_stime={142, 730301}, ...}) = 0 17:36:44 getrusage(RUSAGE_SELF, {ru_utime={125, 122978}, ru_stime={142, 730301}, ...}) = 0 17:36:44 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608455 17:36:44 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608455 17:36:44 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:44 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:44 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608455 17:36:44 semtimedop(6062085, {{16, -1, 0}}, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) – 17:36:47 getrusage(RUSAGE_SELF, {ru_utime={125, 123978}, ru_stime={142, 731301}, ...}) = 0 17:36:47 getrusage(RUSAGE_SELF, {ru_utime={125, 123978}, ru_stime={142, 731301}, ...}) = 0 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608755 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608755 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 read(16, "MSA\0\2\0\10\0P\0\0\0\0\0\0\0\20?P\r\0\0\0\0\0\200\330\266\177\177\0\0"..., 80) = 80 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608756 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608756 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608756 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608756 17:36:47 times({tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}) = 645608756 17:36:47 semtimedop(6062085, {{16, -1, 0}}, 1, {3, 0}^C Process 21395 detached ........................................................................................................................

● 本文作者：小麦苗，部分内容整理自网络，若有侵权请联系小麦苗删除

● 本文在个人微信公众号（ DB宝）上有同步更新

● QQ群号： 230161599 、618766405，微信群私聊

● 个人QQ号（646634621），微信号（db_bao），注明添加缘由

● 于 2020年12月完成

● 最新修改时间：2020年12月

........................................................................................................................

小麦苗的微店： ● 小麦苗出版的数据库类丛书： http://blog.itpub.net/26736162/viewspace-2142121/

小麦苗OCP、OCM、高可用、MySQL、DBA学习班： http://blog.itpub.net/26736162/viewspace-2148098/

● 数据库笔试面试题库及解答： http://blog.itpub.net/26736162/viewspace-2134706/

........................................................................................................................

请扫描下面的二维码来关注小麦苗的微信公众号（ DB宝）及QQ群（230161599、618766405）、添加小麦苗微信（db_bao），学习最实用的数据库技术。

........................................................................................................................

专家姓名：小麦苗

【QQ：646634621】【微信：db_bao】【微信公众号：DB宝】【QQ群：230161599】【Oracle OCP、OCM、高可用（RAC+DG+OGG）、MySQL OCP、PGCA+PGCE+PGCM等都可以找麦老师了】【个人网站：xmmup.com】

注册时间：2012-09-23

10666486

广播电视节目制作经营许可证(京) 字第1234号中国互联网协会会员