主机管理+堡垒机系统开发：strace命令用法详解（六）

一、简单介绍

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

部分输出:

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

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

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

三、strace范例

1、只跟踪与文件操作有关的系统调用

15:02:39.777281 open("/usr/lib/python2.7/site-packages/salt/log/handlers/raven.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.777459 close(3)                = 0
15:02:39.777900 umask(027)              = 022
15:02:39.778027 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
15:02:39.778124 fstat(3, {st_mode=S_IFREG|0644, st_size=1398, ...}) = 0
15:02:39.778171 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.778225 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1398
15:02:39.778291 close(3)                = 0
15:02:39.778342 munmap(0x7f5867d93000, 4096) = 0
15:02:39.778435 stat("/var/log", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
15:02:39.778510 mkdir("/var/log/salt", 0777) = -1 EEXIST (File exists)
15:02:39.778610 stat("/var/log/salt/master", {st_mode=S_IFREG|0644, st_size=182, ...}) = 0
15:02:39.778679 stat("/var/log/salt/master", {st_mode=S_IFREG|0644, st_size=182, ...}) = 0
15:02:39.778745 umask(022)              = 027
15:02:39.778859 access("/var/log/salt/master", F_OK) = 0
15:02:39.778932 access("/var/log/salt/master", W_OK) = 0
15:02:39.779048 stat("/usr/lib64/python2.7/multiprocessing/queues", 0x7ffda84186f0) = -1 ENOENT (No such file or directory)
15:02:39.779115 open("/usr/lib64/python2.7/multiprocessing/queues.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.779171 open("/usr/lib64/python2.7/multiprocessing/queuesmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.779224 open("/usr/lib64/python2.7/multiprocessing/queues.py", O_RDONLY) = 3
15:02:39.779271 fstat(3, {st_mode=S_IFREG|0644, st_size=12318, ...}) = 0
15:02:39.779316 open("/usr/lib64/python2.7/multiprocessing/queues.pyc", O_RDONLY) = 4
15:02:39.779369 fstat(4, {st_mode=S_IFREG|0644, st_size=11595, ...}) = 0
15:02:39.779405 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.780894 fstat(5, {st_mode=S_IFREG|0644, st_size=11080, ...}) = 0
15:02:39.780930 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.780968 read(5, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\6\0\0\0@\0\0\0s\234\1\0\0d\0"..., 4096) = 4096
15:02:39.781010 fstat(5, {st_mode=S_IFREG|0644, st_size=11080, ...}) = 0
15:02:39.781051 read(5, "\0\0R)\0\0\0R\35\0\0\0R0\0\0\0(\0\0\0\0(\0\0\0\0(\0\0\0\0"..., 4096) = 4096
15:02:39.781104 read(5, "\203\1\0\fs7\0t\3\0\202\1\0x4\0|\0\0j\7\0j\5\0t\6\0\203\1\0r"..., 4096) = 2888
15:02:39.781141 read(5, "", 4096)       = 0
15:02:39.781272 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5855598000
15:02:39.781346 close(5)                = 0
15:02:39.781390 munmap(0x7f5867d93000, 4096) = 0
15:02:39.781478 stat("/usr/lib64/python2.7/multiprocessing/forking", 0x7ffda8417bf0) = -1 ENOENT (No such file or directory)
15:02:39.781533 open("/usr/lib64/python2.7/multiprocessing/forking.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.781580 open("/usr/lib64/python2.7/multiprocessing/forkingmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.781618 open("/usr/lib64/python2.7/multiprocessing/forking.py", O_RDONLY) = 5
15:02:39.781654 fstat(5, {st_mode=S_IFREG|0644, st_size=16314, ...}) = 0
15:02:39.781689 open("/usr/lib64/python2.7/multiprocessing/forking.pyc", O_RDONLY) = 6
15:02:39.781727 fstat(6, {st_mode=S_IFREG|0644, st_size=14360, ...}) = 0
15:02:39.781758 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.781794 read(6, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\6\0\0\0@\0\0\0s\23\3\0\0d\0"..., 4096) = 4096
15:02:39.781833 fstat(6, {st_mode=S_IFREG|0644, st_size=14360, ...}) = 0
15:02:39.781903 read(6, "i\0\0\0\0g\374\251\361\322Mb@?i\2\0\0\0g\232\231\231\231\231\231\251?(\5\0\0"..., 8192) = 8192
15:02:39.781963 read(6, "|\0\0d\4\0\31r{\0t\10\0j\t\0\203\0\0\1n\0\0d\5\0|\0\0k\6\0"..., 4096) = 2072
15:02:39.781998 read(6, "", 4096)       = 0
15:02:39.782232 close(6)                = 0
15:02:39.783245 close(5)                = 0
15:02:39.783486 close(4)                = 0
15:02:39.783636 close(3)                = 0
15:02:39.783718 stat("/usr/lib64/python2.7/multiprocessing/connection", 0x7ffda8417ef0) = -1 ENOENT (No such file or directory)
15:02:39.783775 open("/usr/lib64/python2.7/multiprocessing/connection.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.783814 open("/usr/lib64/python2.7/multiprocessing/connectionmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
15:02:39.783875 open("/usr/lib64/python2.7/multiprocessing/connection.py", O_RDONLY) = 3
15:02:39.783916 fstat(3, {st_mode=S_IFREG|0644, st_size=14901, ...}) = 0
15:02:39.783955 open("/usr/lib64/python2.7/multiprocessing/connection.pyc", O_RDONLY) = 4
15:02:39.784003 fstat(4, {st_mode=S_IFREG|0644, st_size=14695, ...}) = 0
15:02:39.784037 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5867d93000
15:02:39.784083 read(4, "\3\363\r\n\1\244H[c\0\0\0\0\0\0\0\0\3\0\0\0@\0\0\0s\210\2\0\0d\0"..., 4096) = 4096
15:02:39.784129 fstat(4, {st_mode=S_IFREG|0644, st_size=14695, ...}) = 0
15:02:39.784167 read(4, "d(\0\0\0\0(\0\0\0\0(\0\0\0\0s2\0\0\0/usr/lib64/"..., 8192) = 8192
15:02:39.784205 read(4, "\0\0NRK\0\0\0R\n\0\0\0t\4\0\0\0pollR\235\0\0\0R\231\0\0\0"..., 4096) = 2407
15:02:39.784239 read(4, "", 4096)       = 0

2、通过pid跟踪进程

[root@saltstack ~]# pgrep salt-maste
14379
14388
14393
14394
14397
14398
14399
14406
14407
14408
14409
14410
14412
strace -tt -f  -e trace=file -p 14407 /usr/bin/salt-master
[pid 19087] 15:07:32.820297 openat(AT_FDCWD, "/var/cache/salt/master/minions/mysql-node1-245", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.820394 stat("/var/cache/salt/master/minions/mysql-node1-245/data.p", {st_mode=S_IFREG|0600, st_size=3084, ...}) = 0
[pid 19087] 15:07:32.820502 stat("/var/cache/salt/master/minions/mysql-node1-245/data.p", {st_mode=S_IFREG|0600, st_size=3084, ...}) = 0
[pid 19087] 15:07:32.820564 lstat("/var/cache/salt/master/minions/mongodb-node2-152", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.820622 openat(AT_FDCWD, "/var/cache/salt/master/minions/mongodb-node2-152", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.820720 stat("/var/cache/salt/master/minions/mongodb-node2-152/data.p", {st_mode=S_IFREG|0600, st_size=2768, ...}) = 0
[pid 19087] 15:07:32.820818 stat("/var/cache/salt/master/minions/mongodb-node2-152/data.p", {st_mode=S_IFREG|0600, st_size=2768, ...}) = 0
[pid 19087] 15:07:32.820896 lstat("/var/cache/salt/master/minions/ccb-credit-notify-114", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.820955 openat(AT_FDCWD, "/var/cache/salt/master/minions/ccb-credit-notify-114", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821053 stat("/var/cache/salt/master/minions/ccb-credit-notify-114/data.p", {st_mode=S_IFREG|0600, st_size=2720, ...}) = 0
[pid 19087] 15:07:32.821153 stat("/var/cache/salt/master/minions/ccb-credit-notify-114/data.p", {st_mode=S_IFREG|0600, st_size=2720, ...}) = 0
[pid 19087] 15:07:32.821217 lstat("/var/cache/salt/master/minions/openstack-compute3-45", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821274 openat(AT_FDCWD, "/var/cache/salt/master/minions/openstack-compute3-45", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821373 stat("/var/cache/salt/master/minions/openstack-compute3-45/data.p", {st_mode=S_IFREG|0600, st_size=4609, ...}) = 0
[pid 19087] 15:07:32.821482 stat("/var/cache/salt/master/minions/openstack-compute3-45/data.p", {st_mode=S_IFREG|0600, st_size=4609, ...}) = 0
[pid 19087] 15:07:32.821547 lstat("/var/cache/salt/master/minions/KVM-node1-9", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821605 openat(AT_FDCWD, "/var/cache/salt/master/minions/KVM-node1-9", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.821703 stat("/var/cache/salt/master/minions/KVM-node1-9/data.p", {st_mode=S_IFREG|0600, st_size=4801, ...}) = 0
[pid 19087] 15:07:32.821802 stat("/var/cache/salt/master/minions/KVM-node1-9/data.p", {st_mode=S_IFREG|0600, st_size=4801, ...}) = 0
[pid 19087] 15:07:32.821881 lstat("/var/cache/salt/master/minions/KVM-files-DB-16", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.821943 openat(AT_FDCWD, "/var/cache/salt/master/minions/KVM-files-DB-16", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.822043 stat("/var/cache/salt/master/minions/KVM-files-DB-16/data.p", {st_mode=S_IFREG|0600, st_size=3365, ...}) = 0
[pid 19087] 15:07:32.822144 stat("/var/cache/salt/master/minions/KVM-files-DB-16/data.p", {st_mode=S_IFREG|0600, st_size=3365, ...}) = 0
[pid 19087] 15:07:32.822207 lstat("/var/cache/salt/master/minions/kvm-compute8-2", {st_mode=S_IFDIR|0755, st_size=19, ...}) = 0
[pid 19087] 15:07:32.822264 openat(AT_FDCWD, "/var/cache/salt/master/minions/kvm-compute8-2", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
[pid 19087] 15:07:32.822361 stat("/var/cache/salt/master/minions/kvm-compute8-2/data.p", {st_mode=S_IFREG|0600, st_size=3156, ...}) = 0
[pid 19087] 15:07:32.822473 stat("/var/cache/salt/master/minions/kvm-compute8-2/data.p", {st_mode=S_IFREG|0600, st_size=3156, ...}) = 0

说明：每个调用的时间花销在调用行最右边的尖括号里面

3、跟踪系统调用统计

[root@saltstack ~]# strace -c /usr/bin/salt-master
[WARNING ] Unable to bind socket 0.0.0.0:4505, error: [Errno 98] Address already in use; Is there another salt-master running?
The salt master is shutdown. The ports are not available to bind
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 42.52    0.003375         482         7           clone
 16.88    0.001340           0      3393      2647 open
  5.96    0.000473           0      1158           read
  5.88    0.000467           0      1572       954 stat
  4.30    0.000341           1       572           mmap
  3.69    0.000293           1       346           munmap
  3.39    0.000269           0       856           close
  3.26    0.000259           0      1219           fstat
  2.36    0.000187           1       171           mprotect
  2.10    0.000167           1       170           getdents
  1.86    0.000148           7        22         1 futex
  1.61    0.000128          18         7           wait4
  1.02    0.000081           1       133        48 openat
  0.84    0.000067           1       116           brk
  0.73    0.000058          19         3           sendmmsg
  0.72    0.000057           1        68           rt_sigaction
  0.44    0.000035           7         5           pipe
  0.42    0.000033           0       220       148 lseek
  0.37    0.000029           3        11         1 ioctl
  0.28    0.000022           2        10           poll
  0.21    0.000017           2         9         6 connect
  0.20    0.000016           3         6           recvfrom
  0.16    0.000013           0        87         6 lstat
  0.16    0.000013           1        23         5 access
  0.13    0.000010           1        10           socket
  0.09    0.000007           0        35           fcntl
  0.08    0.000006           1         6           write
  0.06    0.000005           3         2           mremap
  0.06    0.000005           5         1           execve
  0.04    0.000003           3         1           rt_sigprocmask
  0.04    0.000003           2         2           getrlimit
  0.04    0.000003           3         1           arch_prctl
  0.03    0.000002           0         6           uname
  0.03    0.000002           2         1           set_tid_address
  0.03    0.000002           2         1           set_robust_list
  0.01    0.000001           0         3           getcwd
  0.01    0.000001           0         3           pipe2
  0.00    0.000000           0         2         1 select
  0.00    0.000000           0         1         1 bind
  0.00    0.000000           0         1           setsockopt
  0.00    0.000000           0         1         1 mkdir
  0.00    0.000000           0         3           link
  0.00    0.000000           0         6           unlink
  0.00    0.000000           0         6         2 readlink
  0.00    0.000000           0         2           umask
  0.00    0.000000           0         2           sysinfo
  0.00    0.000000           0        15           getuid
  0.00    0.000000           0         1           getgid
  0.00    0.000000           0         3           geteuid
  0.00    0.000000           0         1           getegid
  0.00    0.000000           0         3         2 statfs
------ ----------- ----------- --------- --------- ----------------
100.00    0.007938                 10303      3823 total

说明：上面的结果将清楚地告诉我们调用了那些系统函数，调用的次数是多少，消耗了多少时间等信息，这对我们分析程序来说是非常有用的

4、重定向输出

strace -c -o tongji.log /usr/bin/salt-master

[root@saltstack ~]# cat tongji.log

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 22.40    0.002689         384         7           clone
 19.96    0.002396           1      3393      2647 open
 12.14    0.001458           1      1572       954 stat
 11.82    0.001419           1      1158           read
  6.43    0.000772           1       856           close
  6.08    0.000730           1      1219           fstat
  3.66    0.000439           1       572           mmap
  3.64    0.000437           1       346           munmap
  2.30    0.000276           2       133        48 openat
  2.16    0.000259           1       220       148 lseek
  2.09    0.000251           1       170           getdents
  1.93    0.000232          33         7           wait4
  1.43    0.000172           1       171           mprotect
  1.10    0.000132           2        87         6 lstat
  0.66    0.000079           1       116           brk
  0.52    0.000062          10         6           write
  0.39    0.000047           2        20         3 futex
  0.37    0.000045           2        23         5 access
  0.27    0.000032           1        35           fcntl
  0.07    0.000009           2         5           pipe
  0.07    0.000008           1        15           getuid
  0.06    0.000007           1        11         1 ioctl
  0.06    0.000007           1         6           uname
  0.04    0.000005           0        68           rt_sigaction
  0.04    0.000005           3         2           mremap
  0.04    0.000005           5         1           execve
  0.04    0.000005           1         6         2 readlink
  0.03    0.000004           1         3           pipe2
  0.02    0.000003           3         1           rt_sigprocmask
  0.02    0.000003           1         3           link
  0.02    0.000003           2         2           getrlimit
  0.02    0.000003           3         1           set_tid_address
  0.02    0.000002           0        10           poll

说明：讲结果重定向到文件中

5、对系统调用进行计时

strace -T tongji.log /usr/bin/salt-master

lseek(5, 0, SEEK_CUR)                   = 641 <0.000020>
lseek(5, 0, SEEK_CUR)                   = 641 <0.000024>
read(5, "", 4096)                       = 0 <0.000020>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 6 <0.000027>
fstat(6, {st_mode=S_IFREG|0644, st_size=26480, ...}) = 0 <0.000019>
mmap(NULL, 26480, PROT_READ, MAP_PRIVATE, 6, 0) = 0x7f03c2a9d000 <0.000024>
close(6)                                = 0 <0.000018>
open("/lib64/tls/x86_64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000027>
stat("/lib64/tls/x86_64", 0x7ffc50377020) = -1 ENOENT (No such file or directory) <0.000022>
open("/lib64/tls/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000026>
stat("/lib64/tls", {st_mode=S_IFDIR|0555, st_size=6, ...}) = 0 <0.000022>
open("/lib64/x86_64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
stat("/lib64/x86_64", 0x7ffc50377020)   = -1 ENOENT (No such file or directory) <0.000021>
open("/lib64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
stat("/lib64", {st_mode=S_IFDIR|0555, st_size=24576, ...}) = 0 <0.000021>
open("/usr/lib64/tls/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000022>
open("/usr/lib64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000031>
munmap(0x7f03c2a9d000, 26480)           = 0 <0.000026>
close(5)                                = 0 <0.000042>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000025>
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000030>
fstat(5, {st_mode=S_IFREG|0644, st_size=1398, ...}) = 0 <0.000020>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f03c2b6c000 <0.000022>
read(5, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1398 <0.000025>
close(5)                                = 0 <0.000021>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000023>
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5 <0.000031>
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000033>
close(5)                                = 0 <0.000023>
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5 <0.000022>
connect(5, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000025>
close(5)                                = 0 <0.000021>
open("/etc/group", O_RDONLY|O_CLOEXEC)  = 5 <0.000037>
fstat(5, {st_mode=S_IFREG|0644, st_size=641, ...}) = 0 <0.000019>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f03c2b6c000 <0.000027>
read(5, "root:x:0:\nbin:x:1:\ndaemon:x:2:\ns"..., 4096) = 641 <0.000026>
close(5)                                = 0 <0.000022>
munmap(0x7f03c2b6c000, 4096)            = 0 <0.000023>
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000051>

说明：每个调用的时间花销在调用行最右边的尖括号里面

四、定位案例

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

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

五、总结

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

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

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

备注：

1、perf原因kernel支持

2、ftrace kernel支持可编程

3、systemtap 功能强大，RedHat系统支持，对用户态，内核态逻辑都能探查，使用范围更广

posted @ 2018-08-18 08:00 活的潇洒80 阅读(910) 评论(0) 编辑收藏举报

刷新页面返回顶部

运维人生

主机管理+堡垒机系统开发：strace命令用法详解（六）

一、简单介绍

strace是什么？

strace能做什么？

启动命令：

输出:

二、strace怎么用？

关于系统调用：

strace常用选项：

三、strace范例

2、通过pid跟踪进程

说明：每个调用的时间花销在调用行最右边的尖括号里面

3、跟踪系统调用统计

说明：上面的结果将清楚地告诉我们调用了那些系统函数，调用的次数是多少，消耗了多少时间等信息，这对我们分析程序来说是非常有用的

4、重定向输出

说明：讲结果重定向到文件中

5、对系统调用进行计时

四、定位案例

1、定位进程异常退出

2、定位共享内存异常

3、性能分析

五、总结

公告

运维人生

主机管理+堡垒机系统开发：strace命令用法详解（六）

一、简单介绍

strace是什么？

strace能做什么？

启动命令：

输出:

二、strace怎么用？

关于系统调用：

strace常用选项：

三、strace范例

2、通过pid跟踪进程

说明：每个调用的时间花销在调用行最右边的尖括号里面

3、跟踪系统调用统计

说明：上面的结果将清楚地告诉我们调用了那些系统函数，调用的次数是多少，消耗了多少时间等信息，这对我们分析程序来说是非常有用的

4、重定向输出

说明：讲结果重定向到文件中

5、对系统调用进行计时

四、定位案例

1、定位进程异常退出

2、定位共享内存异常

3、 性能分析

五、总结

公告

3、性能分析