用户空间调试工具-strace
2019-08-11 14:11:54 阿炯

strace是一个可用于诊断、调试和教学的Linux用户空间跟踪器。我们用它来监控用户空间进程和内核的交互,如系统调用、信号传递、进程状态变更等,其底层使用内核的ptrace特性来实现其功能。它可以从开始到结束跟踪二进制的执行,并在进程的生命周期中输出一行具有系统调用名称,每个系统调用的参数和返回值的文本行。

strace常用来跟踪进程执行时的系统调用和所接收的信号。在Linux世界,进程不能直接访问硬件设备,当进程需要访问硬件设备(比如读取磁盘文件,接收网络数据等等)时,必须由用户态模式切换至内核态模式,通过系统调用访问硬件设备。strace可以跟踪到一个进程产生的系统调用,就可以跟踪到一个进程产生的系统调用,包括参数、返回值、执行消耗的时间、调用次数、成功和失败的次数。

strace命令是一个集诊断、调试、统计与一体的工具,我们可以使用strace对应用的系统调用和信号传递的跟踪结果来对应用进行分析,以达到解决问题或者是了解应用工作过程的目的。当然strace与专业的调试工具比如说gdb之类的是没法相比的,因为它不是一个专业的调试器。strace的最简单的用法就是执行一个指定的命令,在指定的命令结束之后它也就退出了。在命令执行的过程中,strace会记录和解析命令进程的所有系统调用以及这个进程所接收到的所有的信号值。

strace-linux syscall tracer


strace is a diagnostic, debugging and instructional userspace utility for Linux. It is used to monitor and tamper with interactions between processes and the Linux kernel, which include system calls, signal deliveries, and changes of process state.

System administrators, diagnosticians and trouble-shooters will find it invaluable for solving problems with programs for which the source is not readily available since they do not need to be recompiled in order to trace them.

对一个经验丰富的 Linux C/C++ 工程师可通过 strace 即可分析多数软件的大致实现方式。Linux 进程空间可分为用户空间和内核空间,程序通常运行在用户态,它需要通过系统调用访问内核空间。系统调用的重要性不言而喻,凡是涉及到进程、文件管理、设备管理和通信等的操作都必须依赖系统调用完成,如下:
Process Control: load/execute/end/abort/create/terminate process, get/set process attributes, wait for time/event/signal, allocate/free memory
File management: create/delete/open/read/write/reposition file, get/set file attributes
Device Management: request/release/attach/detach device,read/write/reposition, get/set device attributes
Communication: create/delete connection, send/receive messages, transfer status information


strace 追踪进程产生的所有系统调用,包括参数、返回值和执行消耗的时间,很多是涉及到内核和资源层面的操作都需要系统调用完成,所以 strace 在诊断以下场景非常有效:
程序意外退出
程序运行缓慢
进程阻塞


strace用途

它可以基于特定的系统调用或系统调用组进行过滤
它可以通过统计特定系统调用的使用次数,所花费的时间,以及成功和错误的数量来分析系统调用的使用
它跟踪发送到进程的信号
可以通过pid附加到任何正在运行的进程
调试性能问题,查看系统调用的频率,找出耗时的程序段
查看程序读取的是哪些文件从而定位比如配置文件加载错误问题
查看程序长时间运行"假死"情况
当程序出现"Out of memory"时被系统发出的SIGKILL信息所kill
另外因为strace拿到的是系统调用相关信息,一般也即是IO操作信息,这个对于排查比如cpu占用100%问题是无能为力的,这个时候就可以使用GDB工具了

关于系统调用:
按维基百科中的解释,在计算机中,系统调用(英语: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 选项即可。

比如,有个在运行的freeoa_server服务,查看其pid:
pidof freeoa_server                      
1803

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

完成跟踪时,按ctrl + C 结束strace即可。

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

跟踪可执行程序
# strace -f -F -o ~/straceout.txt freeoapp

-f -F选项告诉strace同时跟踪fork和vfork出来的进程,-o选项把所有strace输出写到~/straceout.txt里 面,myserver是要启动和调试的程序。

跟踪服务程序
# strace -o output.txt -T -tt -e trace=all -p 2897

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


参数

-c 统计每一系统调用的所执行的时间,次数和出错的次数等.
-d 输出strace关于标准错误的调试信息.
-f 跟踪由fork调用所产生的子进程.
-ff 如果提供-o filename,则所有进程的跟踪结果输出到相应的filename.pid中,pid是各进程的进程号.
-F 尝试跟踪vfork调用.在-f时,vfork不被跟踪.
-h 输出简要的帮助信息.
-i 输出系统调用的入口指针.
-q 禁止输出关于脱离的消息.
-r 打印出相对时间关于,,每一个系统调用.
-t 在输出中的每一行前加上时间信息.
-tt 在输出中的每一行前加上时间信息,微秒级.
-ttt 微秒级输出,以秒了表示时间.
-T 显示每一调用所耗的时间.
-v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出.
-V 输出strace的版本信息.
-x 以十六进制形式输出非标准字符串
-xx 所有字符串以十六进制形式输出.
-a column
设置返回值的输出位置.默认 为40.
-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使用!来执行历史记录里的命令,所以要使用\\.
-e trace=set
只跟踪指定的系统 调用.例如:-e trace=open,close,rean,write表示只跟踪这四个系统调用.默认的为set=all.
-e trace=file
只跟踪有关文件操作的系统调用.
-e trace=process
只跟踪有关进程控制的系统调用.
-e trace=network
跟踪与网络有关的所有系统调用.
-e strace=signal
跟踪所有与系统信号有关的 系统调用
-e trace=ipc
跟踪所有与进程通讯有关的系统调用
-e abbrev=set
设定 strace输出的系统调用的结果集.-v 等与 abbrev=none.默认为abbrev=all.
-e raw=set
将指 定的系统调用的参数以十六进制显示.
-e signal=set
指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号.
-e read=set
输出从指定文件中读出 的数据.例如:
-e read=3,5
-e write=set
输出写入到指定文件中的数据.
-o filename
将strace的输出写入文件filename
-p pid
跟踪指定的进程pid.
-s strsize
指定输出的字符串的最大长度.默认为32.文件名一直全部输出.
-u username
以username 的UID和GID执行被跟踪的命令


常用选项

从一个示例命令来看:strace -tt -T -v -f -e trace=file -o /var/log/strace.log -s 1024 -p 3489

-tt 在每行输出的前面,显示毫秒级别的时间
-T 显示每次系统调用所花费的时间
-v 对于某些相关调用,把完整的环境变量,文件stat结构等打出来。
-f 跟踪目标进程,以及目标进程创建的所有子进程
-e 控制要跟踪的事件和跟踪行为,比如指定要跟踪的系统调用名称
-o 把strace的输出单独写到指定的文件
-s 当系统调用的某个参数是字符串时,最多输出指定长度的内容,默认是32个字节
-p 指定要跟踪的进程pid, 要同时跟踪多个pid, 重复多次-p选项即可。

实例:跟踪nginx, 看其启动时都访问了哪些文件
strace -tt -T -f -e trace=file -o /var/log/strace.log -s 1024 ./nginx

部分输出:
...

输出中,第一列显示的是进程的pid, 接着是毫秒级别的时间,这个是-tt 选项的效果。

每一行的最后一列,显示了该调用所花的时间,是-T选项的结果。

这里的输出只显示和文件访问有关的内容,这是因为我们通过-e trace=file 选项指定了。

这里特别说下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什么也匹配不上。


当发现进程或服务异常时可以通过strace来跟踪其系统调用,"看看它在干什么",进而找到异常的原因。熟悉常用系统调用,能够更好地理解和使用strace。当然它也不是万能的,当目标进程卡死在用户态时,strace就没有输出了。这个时候我们需要其他的跟踪手段,比如gdb/perf/SystemTap等工具了。

备注:
1、perf原因kernel支持
2、ftrace  kernel支持可编程
3、systemtap 功能强大,对用户态,内核态逻辑都能探查,使用范围更广

将strace和pstack工具组合使用

strace跟踪程序使用的底层系统调用,可输出系统调用被执行的时间点以及各个调用耗时;pstack工具对指定PID的进程输出函数调用栈,用于输出正在运行的进程的栈跟踪信息。使用strace跟踪出具体耗时的系统调用,再到使用pstack查到程序中具体的耗时函数,一步步找到了影响程序运行时间的程序代码。更多地了解底层,从操作系统层面着手,更有助于程序性能分析与优化。

pstack实际上是gstack的一个链接,而gstack本身是基于gdb封装的shell脚本。该命令必须由相应进程的属主或 root 运行,可以使用 pstack 来确定进程挂起的位置。此命令允许使用的唯一选项是要检查的进程的 PID。与jstack功相比,它能对潜在的死锁予以提示,而pstack只提供了线索,需要gdb进一步的确定。pstack是gdb的一部分,如果系统没有pstack命令,使用yum搜索安装gdb即可。

pstack查看函数堆栈

pstack是一个脚本工具,其核心实现就是使用了gdb以及thread apply all bt命令,下面我们使用pstack查看server进程函数堆栈:
# sh pstack.sh 6739
#0 0x00002ba1f8152650 in __nanosleep_nocancel () from /lib64/libc.so.6
#1 0x00002ba1f8152489 in sleep () from /lib64/libc.so.6
#2 0x00000000004007bb in ha_ha ()
#3 0x0000000000400a53 in main ()

从以上信息可以看出,函数调用关系为:main->ha_ha->sleep,因而我们可以找到ha_ha函数进行分析和优化修改。可以在一段时间内,多执行几次pstack,若发现代码栈总是停在同一个位置,那个位置就需要重点关注,很可能就是出问题的地方。

strace常用来跟踪进程执行时的系统调用和所接收的信号。在linux世界,进程不能直接访问硬件设备,当进程需要访问硬件设备(比如读取磁盘文件,接收网络数据等等)时,必须由用户态模式切换至内核态模式,通过系统调用访问硬件设备。strace可以跟踪到一个进程产生的系统调用,包括参数,返回值,执行消耗的时间。

pstree以树结构显示进程
pstree -p work | grep freeoa


盘点一些常用的用法


Trace Linux Process PID
strace -p 3568

Get Summary of Linux Process
strace -c -p 3568

Print Instruction Pointer During System Call
strace -i df -h

Show Time of Day For Each Trace Output Line
strace -t df -h

Print Command Time Spent in System Calls
strace -T df -h

Trace Only Specific System Calls
strace -e trace=write df -h

trace=write is known as a qualifying expression, where trace is a qualifier (others include signal, abbrev, verbose, raw, read, or write). Here, write is the value of the qualifier.

Trace System Calls Based on a Certain Condition
strace -q -e trace=process df -h
strace -q  -e trace=file df -h
strace -q -e trace=memory df -h
strace -e trace=network df -h
strace -e trace=signal df -h

Redirect Trace Output to File
strace -o df_debug.txt df -h

Show Some Debugging Output of Strace
strace -d df -h

strace问题定位案例

1、定位进程异常退出

问题:机器上有个叫做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为退出码)。可能有人会疑惑,代码里面明明调用的是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 ))
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个进程!而进程创建和销毁的代价是相当高的,性能不差才怪。

4、调试程序

在理想世界里,每当一个程序不能正常执行一个功能时,它就会给出一个有用的错误提示,告诉你在足够的改正错误的线索。但遗憾的是,我们不是生活在理想世界里,起码不总是生活在理想世界里。有时候一个程序出现了问题,你无法找到原因。

这就是调试程序出现的原因。strace是一个必不可少的调试工具,strace用来监视系统调用。你不仅可以调试一个新开始的程序,也可以调试一个已经在运行的程序(把strace绑定到一个已有的PID上 面)。首先让我们看一个真实的例子:启动KDE时出现问题:前一段时间,我在 启动KDE的时候出了问题,KDE的错误信息无法给我任何有帮助的线索。

_KDE_IceTransSocketCreateListener: failed to bind listener
_KDE_IceTransSocketUNIXCreateListener: ...SocketCreateListener() failed
_KDE_IceTransMakeAllCOTSServerListeners: failed to create listener for local

Cannot establish any listening sockets DCOPServer self-test failed.

对我来说这个错误信息没有太多意义,只是一个对KDE来说至关重要的负责进程间通信的程序无法启动。我还可以知道这个错误和ICE协议(Inter Client Exchange)有关,除此之外,我不知道什么是KDE启动出错的原因。于是决定采用strace看一下在启动 dcopserver时到底程序做了什么:
strace -f -F -o ~/dcop-strace.txt dcopserver

这里 -f -F选项告诉strace同时跟踪fork和vfork出来的进程,-o选项把所有strace输出写到~/dcop-strace.txt里 面,dcopserver是要启动和调试的程序。再次出现错误之后,检查了错误输出文件dcop-strace.txt,文件里有很多系统调用的记录。在程序运行出错前的有关记录如下:
27207 mkdir("/tmp/.ICE-unix", 0777) = -1 EEXIST (File exists)
27207 lstat64("/tmp/.ICE-unix", {st_mode=S_IFDIR|S_ISVTX|0755, st_size=4096, ...}) = 0
27207 unlink("/tmp/.ICE-unix/dcop27207-1066844596") = -1 ENOENT (No such file or directory)
27207 bind(3, {sin_family=AF_UNIX, path="/tmp/.ICE-unix/dcop27207-1066844596"}, 38) = -1 EACCES (Permission denied)
27207 write(2, "_KDE_IceTrans", 13) = 13
27207 write(2, "SocketCreateListener: failed to "..., 46) = 46
27207 close(3) = 0 27207 write(2, "_KDE_IceTrans", 13) = 13
27207 write(2, "SocketUNIXCreateListener: ...Soc"..., 59) = 59
27207 umask(0) = 0 27207 write(2, "_KDE_IceTrans", 13) = 13
27207 write(2, "MakeAllCOTSServerListeners: fail"..., 64) = 64
27207 write(2, "Cannot establish any listening s"..., 39) = 39

其中第一行显示程序试图创建/tmp/.ICE-unix目录,权限为0777,这个操作因为目录已经存在而失败了。第二个系统调用(lstat64)检查了目录状态,并显示这个目录的权限是0755,这里出现了第一个程序运行错误的线索:程序试图创建属性为0777的目录,但是已经存在了一个属性为0755的目录。第三个系统调用(unlink)试图删除一个文件,但是这个文件并不存在。这并不奇怪,因为这个操作只是试图删掉可能存在的老文件。

但是,第四行确认了错误所在。他试图绑定到/tmp/.ICE-unix/dcop27207-1066844596,但是出现了拒绝访问错误。.ICE_unix目录的用户和组都是root,并且只有所有者具有写权限。一个非root用户无法在这个目录下面建立文件,如果把目录属性改成0777, 则前面的操作有可能可以执行,而这正是第一步错误出现时进行过的操作。

所以运行了chmod 0777 /tmp/.ICE-unix之后KDE就可以正常启动了,问题解决了,用strace进行跟踪调试只需要花很短的几分钟时间跟踪程序运行,然后检查并分 析输出文件。

说明:运行chmod 0777只是一个测试,一般不要把一个目录设置成所有用户可读写,同时不设置粘滞位(sticky bit)。给目录设置粘滞位可以阻止一个用户随意删除可写目录下面其他人的文件。一般你会发现/tmp目录因为这个原因设置了粘滞位。KDE可以正常启动 之后,运行chmod +t /tmp/.ICE-unix给.ICE_unix设置粘滞位。

5、解决库依赖问题

starce 的另一个用处是解决和动态库相关的问题。当对一个可执行文件运行ldd时,它会告诉你程序使用的动态库和找到动态库的位置。但是如果你正在使用一个比较老的glibc版本(2.2或更早),你可能会有一个有bug的ldd程序,它可能会报告在一个目录下发现一个动态库,但是真正运行程序时动态连接程序 (/lib/ld-linux.so.2)却可能到另外一个目录去找动态连接库。这通常因为/etc/ld.so.conf和 /etc/ld.so.cache文件不一致,或者/etc/ld.so.cache被破坏。在glibc 2.3.2版本上这个错误不会出现,可能ld-linux的这个bug已经被解决了。

尽管这样,ldd并不能把所有程序依赖的动态库列出来,系统调用dlopen可以在需要的时候自动调入需要的动态库,而这些库可能不会被ldd列出来。作为glibc的一部分的NSS(Name Server Switch)库就是一个典型的例子,NSS的一个作用就是告诉应用程序到哪里去寻找系统帐号数据库。应用程序不会直接连接到NSS库,glibc则会通过dlopen自动调入NSS库。如果这样的库偶然丢失,你不会被告知存在库依赖问题,但这样的程序就无法通过用户名解析得到用户ID了。让我们看一个例子:
whoami程序会给出你自己的用户名,这个程序在一些需要知道运行程序的真正用户的脚本程序里面非常有用,whoami的一个示例 输出如下:
# whoami
root

假设因为某种原因在升 级glibc的过程中负责用户名和用户ID转换的库NSS丢失,我们可以通过把nss库改名来模拟这个环境:
# mv /lib/libnss_files.so.2 /lib/libnss_files.so.2.backup
# whoami
whoami: cannot find username for UID 0

这里你可以看到,运行whoami时出现了错误,ldd程序的输出不会提供有用的帮助:
# ldd /usr/bin/whoami
libc.so.6 => /lib/libc.so.6 (0x4001f000)
/lib/ld-linux.so.2 => /lib/ld-linux.so.2 (0x40000000)

你只会看到whoami依赖Libc.so.6和ld-linux.so.2,它没有给出运行whoami所必须的其他库。这里时用strace跟踪 whoami时的输出:
strace -o whoami-strace.txt whoami

open("/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/lib/i686/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686/mmx", 0xbffff190) = -1 ENOENT (No such file or directory)
open("/lib/i686/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/i686", 0xbffff190) = -1 ENOENT (No such file or directory)
open("/lib/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib/mmx", 0xbffff190) = -1 ENOENT (No such file or directory)
open("/lib/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/lib", {st_mode=S_IFDIR|0755, st_size=2352, ...}) = 0
open("/usr/lib/i686/mmx/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
stat64("/usr/lib/i686/mmx", 0xbffff190) = -1 ENOENT (No such file or directory)
open("/usr/lib/i686/libnss_files.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)

你可以发现在不同目录下面查找libnss.so.2的尝试,但是都失败了。如果没有strace这样的工具,很难发现这个错误是由于缺少动态库造成的。现 在只需要找到libnss.so.2并把它放回到正确的位置就可以了。 

6、限制strace只跟踪特定的系统调用

如果你已经知道你要找什么,你可以让strace只跟踪一些类型的系统调用。例如,需要看看在configure脚本里面执行的程序,需要监视的系统调用就是execve。让strace只记录execve的调用用这个命令:
strace -f -o configure-strace.txt -e execve ./configure

7、一例高CPU 用量的排查过程

在本例中大家很容易发现 CPU 主要是被若干个应用程序进程占用了,同时占用的比较多的内存,不过系统物理内存尚有结余,SWAP 也不严重,这并不是问题主因。在 CPU 列表中能看到 CPU 主要消耗在内核态sy,而不是用户态us,和我们的经验不符。Linux 操作系统有很多用来跟踪程序行为的工具,内核态的函数调用跟踪用strace,用户态的函数调用跟踪用ltrace,所以这里我们应该用strace:

# strace -p <PID>

不过如果直接用 strace 跟踪某个进程的话,往往是满屏翻滚的字符,想从这里看出问题的症结并不是一件容易的事情,好在 strace  可以按操作汇总时间:
# strace -cp <PID>

通过c选项用来汇总各个操作的总耗时
# strace -cp

很明显,我们能看到 CPU 主要被 clone 操作消耗了,还可以单独跟踪一下 clone:
# strace -T -e clone -p <PID>

通过T选项可以获取操作实际消耗的时间,通过e选项可以跟踪某个操作:
# strace -T -e clone -p

很明显,一个 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 -eclone php -r 'exec("ls");'

如果我们用 strace 跟踪一个进程,输出结果很少,是不是说明进程很空闲?其实试试 ltrace,可能会发现别有洞天,还要记住有内核态和用户态之分。再看一例php服务器却频现高负载,nginx出现错误日志:
connect() failed (110: Connection timed out) while connecting to upstream
connect() failed (111: Connection refused) while connecting to upstream

看上去是upstream的后端出了问题,统计一下各个系统调用的耗时情况:
# strace -c -p $(pgrep -n php-cgi)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.53    0.023554         132       179           brk
...


看上去brk非常可疑,它竟然耗费了三成的时间,保险起见,单独确认一下:
# strace -T -e brk -p $(pgrep -n php-cgi)
...

在Strace中和操作花费时间相关的选项有两个,分别是-r和-T,它们的差别是-r表示相对时间,而-T表示绝对时间。简单统计可以用-r,但是需要注意的是在多任务背景下,CPU随时可能会被切换出去做别的事情,所以相对时间不一定准确,此时最好使用-T,在行尾可以看到操作时间,可以发现确实很慢。

在继续定位故障原因前,我们先通过man brk来查询一下它的含义:
brk() sets the end of the data segment to the value specified by end_data_segment, when that value is reasonable, the system does have enough memory and the process does not exceed its max data size (see setrlimit(2)).

简单点说就是内存不够用时通过它来申请新内存(data segment):
# strace -T -p $(pgrep -n php-cgi) 2>&1 | grep -B 10 brk

通过grep我们很方便就能获取相关的上下文,反复运行几次,发现每当请求某些脚本时,就会出现若干条耗时的brk,而且这些PHP脚本有一个共同的特点,就是非常大,甚至有几百K,为何会出现这么大的PHP脚本?实际上是程序员为了避免数据库操作,把非常庞大的数组变量通过var_export持久化到PHP文件中,然后在程序中通过include来获取相应的变量,因为变量太大,所以PHP不得不频繁执行brk,不幸的是在本例的环境中,此操作比较慢,从而导致处理请求的时间过长,加之PHP进程数有限,于是乎在Nginx上造成请求拥堵,最终导致高负载故障。

通过开发人员的修改调整后,brk已经不见了,取而代之的是recvfrom和accept,不过这些操作本来就是很耗时的,所以可以定位brk就是故障的原因。



最新版本:


官方主页:https://strace.io/