Linux 调试之strace

前言

strace命令是Linux系统调用跟踪器，可以跟踪系统调用，为每个系统调用打印一行信息，还可以计算系统调用并打印报告。

可以用来分析应用和内核的边界：系统调用。

strace - trace system calls and signals
strace is a useful diagnostic, instructional, and debugging tool.
1
2

在最简单的情况下，strace运行指定的命令，直到退出为止。它拦截并记录进程调用的系统调用和进程接收到的信号。每个系统调用的名称、它的参数及其返回值将打印在标准错误中或用-o选项指定的文件中。
跟踪中的每一行都包含系统调用名称，后面括号中的是参数以及返回值。

strace 可以跟踪进程的系统调用、特定的系统调用以及系统调用的执行时间。很多时候，我们通过系统调用的执行时间，就能判断出业务延迟发生在哪里。

一、strace 例子

1.1 strace 跟踪 free

每3S展示一次free的结果。

[root@localhost ~]# free -s 3
              total        used        free      shared  buff/cache   available
Mem:        7890812      873948      874728      133896     6142136     6401416
Swap:       8126460           0     8126460

              total        used        free      shared  buff/cache   available
Mem:        7890812      874264      874408      133896     6142140     6401096
Swap:       8126460           0     8126460

              total        used        free      shared  buff/cache   available
Mem:        7890812      874152      874488      133896     6142172     6401176

......
1
2
3
4
5
6
7
8
9
10
11
12
13

 -s, --seconds seconds
 	Continuously  display  the  result  delay  seconds  apart.  
1
2

[root@localhost strace]# strace -ttt -T -p `pidof free`
strace: Process 3636 attached
1669012085.343662 restart_syscall(<... resuming interrupted nanosleep ...>) = 0 <0.285379>
1669012085.629251 lseek(3, 0, SEEK_SET) = 0 <0.000134>
1669012085.629664 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000524>
1669012085.630510 write(1, "              total        used "..., 80) = 80 <0.000098>
1669012085.630829 write(1, "Mem:        7890812      874880 "..., 80) = 80 <0.000092>
1669012085.631079 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000095>
1669012085.631308 write(1, "\n", 1)     = 1 <0.000091>
1669012085.631486 nanosleep({3, 0}, NULL) = 0 <3.000331>

1669012088.632074 lseek(3, 0, SEEK_SET) = 0 <0.000148>
1669012088.632422 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000539>
1669012088.633246 write(1, "              total        used "..., 80) = 80 <0.000150>
1669012088.633597 write(1, "Mem:        7890812      875304 "..., 80) = 80 <0.000235>
1669012088.634127 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000209>
1669012088.634640 write(1, "\n", 1)     = 1 <0.000175>
1669012088.635075 nanosleep({3, 0}, NULL) = 0 <3.000270>

1669012091.635563 lseek(3, 0, SEEK_SET) = 0 <0.000130>
1669012091.635878 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000592>
1669012091.636697 write(1, "              total        used "..., 80) = 80 <0.000141>
1669012091.637126 write(1, "Mem:        7890812      875428 "..., 80) = 80 <0.000146>
1669012091.637435 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000122>
1669012091.637655 write(1, "\n", 1)     = 1 <0.000086>
......
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

free的数据来源于 /proc/meminfo 文件。

[root@localhost strace]# strace -e open free
......
open("/proc/meminfo", O_RDONLY)         = 3
......
1
2
3
4

-t          在跟踪的每一行前加上当前的时间。

-tt         两个t,则打印的时间将包括微秒。

-ttt        三个t, 打印time-since-epoch的第一列，以秒为单位，分辨率为微秒。
1
2
3
4
5

[root@localhost strace]# strace -t -T -p `pidof free`
strace: Process 15738 attached
14:55:30 restart_syscall(<... resuming interrupted nanosleep ...>) = 0 <1.943591>
14:55:32 lseek(3, 0, SEEK_SET)          = 0 <0.000134>
14:55:32 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000558>
14:55:32 write(1, "              total        used "..., 80) = 80 <0.000173>
14:55:32 write(1, "Mem:        7890812      874128 "..., 80) = 80 <0.000102>
14:55:32 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000147>
14:55:32 write(1, "\n", 1)              = 1 <0.000269>
14:55:32 nanosleep({3, 0}, NULL)        = 0 <3.000239>

1
2
3
4
5
6
7
8
9
10
11

[root@localhost strace]# strace -tt -T -p `pidof free`
strace: Process 15738 attached
14:55:19.844415 restart_syscall(<... resuming interrupted nanosleep ...>) = 0 <0.806829>
14:55:20.651494 lseek(3, 0, SEEK_SET)   = 0 <0.000147>
14:55:20.651856 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000490>
14:55:20.652657 write(1, "              total        used "..., 80) = 80 <0.000206>
14:55:20.653144 write(1, "Mem:        7890812      874612 "..., 80) = 80 <0.000168>
14:55:20.653579 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000211>
14:55:20.654084 write(1, "\n", 1)       = 1 <0.000100>
14:55:20.654325 nanosleep({3, 0}, NULL) = 0 <3.000433>

1
2
3
4
5
6
7
8
9
10
11

[root@localhost strace]# strace -ttt -T -p `pidof free`
strace: Process 15738 attached
1669013708.811926 restart_syscall(<... resuming interrupted nanosleep ...>) = 0 <2.833180>
1669013711.645309 lseek(3, 0, SEEK_SET) = 0 <0.000138>
1669013711.645745 read(3, "MemTotal:        7890812 kB\nMemF"..., 8191) = 1282 <0.000464>
1669013711.646423 write(1, "              total        used "..., 80) = 80 <0.000082>
1669013711.646641 write(1, "Mem:        7890812      874800 "..., 80) = 80 <0.000119>
1669013711.646886 write(1, "Swap:       8126460           0 "..., 44) = 44 <0.000091>
1669013711.647057 write(1, "\n", 1)     = 1 <0.000092>
1669013711.647263 nanosleep({3, 0}, NULL) = 0 <3.000412>

1
2
3
4
5
6
7
8
9
10
11

-T ： 显示系统调用花费的时间。这将记录每个系统调用的开始和结束之间的时间差。
1

-p pid：附加到进程 ID pid 的进程并开始跟踪。 跟踪可以随时通过键盘中断信号 (CTRL-C) 终止。 strace 将通过将自己与跟踪的进程分离来做出响应，让它（它们）继续运行。支持-p `pidof PROG` 语法。
1

1.2 strace 跟踪 dd

-c选项可用于总结系统调用活动，计算每次系统调用的时间、调用次数和错误，并在程序退出时报告跟踪信息。
下面的示例还调用并跟踪一个命令(dd)，而不是附加到PID上。
输出结果中，从第三行开始是strace的跟踪信息

[root@localhost strace]#  strace -c dd if=/dev/zero of=/dev/null bs=1k count=5000k
5120000+0 records in
5120000+0 records out
5242880000 bytes (5.2 GB) copied, 143.784 s, 36.5 MB/s
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 50.33   10.667418           2   5120003           read
 49.67   10.526616           2   5120003           write
  0.00    0.000280          23        12         6 open
  0.00    0.000117          13         9           mmap
  0.00    0.000052           6         9           close
  0.00    0.000036           9         4           brk
  0.00    0.000031           8         4           fstat
  0.00    0.000023           6         4           mprotect
  0.00    0.000019          10         2           dup2
  0.00    0.000017          17         1         1 access
  0.00    0.000013          13         1           execve
  0.00    0.000009           9         1           lseek
  0.00    0.000009           9         1           arch_prctl
  0.00    0.000005           3         2           munmap
  0.00    0.000000           0         4           rt_sigaction
------ ----------- ----------- --------- --------- ----------------
100.00   21.194645              10240060         7 total
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

上述执行了5000k次数的read操作和5000k次数的write操作，每次读写操作分别是2微妙。上述dd命令执行了多次系统调用，使用strace跟踪dd将会产生较大的开销。

time: 显示 system CPU time 花费的百分比
seconds: 总的 system CPU time, 单位是秒
usecs/call: 每次调用的平均 system CPU time，以微秒为单位
calls: 系统调用次数
syscall: 系统调用的名字
1
2
3
4
5

其中 system CPU time就是命令在内核中运行的时间，独立于wall clock time。

下面是没有使用strace跟踪 dd命令，执行速度非常块，可见strace开销非常大。

[root@localhost strace]# dd if=/dev/zero of=/dev/null bs=1k count=5000k
5120000+0 records in
5120000+0 records out
5242880000 bytes (5.2 GB) copied, 4.80228 s, 1.1 GB/s
1
2
3
4

当前版本的strace通过Linux ptrace接口使用基于断点的跟踪。这将为所有系统调用的入口和返回设置断点(即使使用-e选项只选择跟踪一些指定的系统调用)。具有高系统调用率的应用程序可能会发现它们的性能降低了一个数量级。

使用strace所花费的时间：

143.784 s, 36.5 MB/s
1

没有使用strace所花费的时间：

4.80228 s, 1.1 GB/s
1

可见使用strace所花费的时间提高了几十倍，因为dd执行系统调用的频率非常高。

因此不推荐在生产环境中使用strace应用程序，特别是该应用程序调用系统调用非常频繁，因为strace会在每个系统调用处设置一个断点，开销非常大，目标进程每执行一次系统调用都会被打断，等 strace 处理完后，目标进程才能继续执行，这就会给目标进程带来比较明显的延迟。

根据应用程序需求，可以在短时间内使用这种样式的跟踪来确定被调用的系统调用类型。如果开销不是问题，strace会更有用。其他类型的跟踪程序，包括perf、Ftrace、BCC和bpftrace，通过使用缓冲跟踪大大减少了跟踪开销，其中事件被写入共享内核环缓冲区，用户级跟踪程序定期读取缓冲区。这减少了用户和内核上下文之间的上下文切换，降低了开销。

未来版本的 strace 可能会通过成为 perf trace 子命令的别名来解决其开销问题。
比如：

strace  ls
1

perf trace ls
1

上述两者结果一样。

perf 提供了一个 trace 子命令，是取代 strace 的首选工具。相对于 ptrace 机制（strace 基于系统调用 ptrace 实现）来说，perf trace 基于内核事件，事件被写入共享内核环缓冲区，自然要比进程跟踪的性能好很多。

1.3 strace 其他一些使用选项

跟踪进程的线程：

-f          Trace  child  processes  as  they  are  created by currently traced processes as a result of the fork(2), vfork(2) and clone(2) system
            calls.  Note that -p PID -f will attach all threads of process PID if it is multi-threaded, not only thread with thread_id = PID.

-ff         If the -o filename option is in effect, each processes trace is written to filename.pid where pid is the numeric process  id  of  each
            process.  This is incompatible with -c, since no per-process counts are kept.

1
2
3
4
5
6

将跟踪的结果写入到指定的文件中filename：

-o filename Write  the trace output to the file filename rather than to stderr.  Use filename.pid if -ff is used.  If the argument begins with '|'
                  or with '!' then the rest of the argument is treated as a command and all output is piped to it.  This is convenient  for  piping  the
                  debugging output to a program without affecting the redirections of executed programs.
1
2
3

跟踪指定的系统调用：

-e trace=set
            Trace  only  the  specified set of system calls.  The -c option is useful for determining which system calls might be useful to trace.
            For example, trace=open,close,read,write means to only trace those four system calls.  Be careful when  making  inferences  about  the
            user/kernel boundary if only a subset of system calls are being monitored.  The default is trace=all.

-e trace=file
            Trace   all   system   calls   which   take   a   file  name  as  an  argument.   You  can  think  of  this  as  an  abbreviation  for
            -e trace=open,stat,chmod,unlink,...  which is useful to seeing what files the process is referencing.  Furthermore, using the abbrevi‐
            ation will ensure that you don't accidentally forget to include a call like lstat in the list.  Betchya woulda forgot that one.

-e trace=process
            Trace all system calls which involve process management.  This is useful for watching the fork, wait, and exec steps of a process.

-e trace=network
            Trace all the network related system calls.

-e trace=signal
            Trace all signal related system calls.

-e trace=ipc
            Trace all IPC related system calls.

-e trace=desc
            Trace all file descriptor related system calls.

-e trace=memory
            Trace all memory mapping related system calls.

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
28

二、strace 原理

2.1 ptrace简介

strace 基于系统调用 ptrace 实现：

NAME
       ptrace - process trace

SYNOPSIS
       #include 

       long ptrace(enum __ptrace_request request, pid_t pid,
                   void *addr, void *data);
1
2
3
4
5
6
7
8

ptrace()系统调用提供了一种方法，通过这种方法，一个进程(“跟踪者”)可以观察和控制另一个进程(“被跟踪者”)的执行，并检查和更改被跟踪者的内存和寄存器。它主要用于实现断点调试和系统调用跟踪（strace 和 gdb的底层实现都是通过 ptrace 实现）。
跟踪者：the tracer
被跟踪者：the tracee

tracee 首先需要附加到 tracer。 附加和后续命令是针对每个线程的：在多线程进程中，每个线程都可以单独附加到一个（可能不同的）tracer，或者不附加，因此不进行调试。 因此，tracee总是意味着（一个）线程，而不是一个（可能是多线程的）进程。

Ptrace 命令总是使用以下形式的调用发送到特定的跟踪对象（tracee）：

ptrace(PTRACE_foo, pid, ...)
1

其中pid是对应Linux线程的线程ID。

进程可以通过调用 fork 并让生成的子进程执行 PTRACE_TRACEME 来启动跟踪，然后（通常）执行 execve。 或者，一个进程可以使用 PTRACE_ATTACH 或 PTRACE_SEIZE 开始跟踪另一个进程。

在被跟踪时，每次发送信号时 the tracee 都会停止，即使信号被忽略也是如此（一个例外是 SIGKILL）。the tracer将在下次调用 waitpid（或相关的“等待”系统调用之一）时得到通知； 该调用将返回一个状态值，其中包含指示 the tracee 停止原因的信息。 当 the tracee 停止时，the tracer 可以使用各种 ptrace 请求来检查和修改 the tracee。 然后 the tracer 使 the tracee 继续，可选择地忽略传递的信号（或者甚至传递不同的信号）。

2.2 strace 原理

strace 原理图如下所示：

对于正在运行的进程而言，strace 可以 attach 到目标进程上，这是通过 ptrace 这个系统调用实现的。ptrace 的 PTRACE_SYSCALL 会去追踪目标进程的系统调用；目标进程被追踪后，每次进入 syscall，都会产生 SIGTRAP 信号并暂停执行；追踪者通过目标进程触发的 SIGTRAP 信号，就可以知道目标进程进入了系统调用，然后追踪者会去处理该系统调用，我们用 strace 命令观察到的信息输出就是该处理的结果；追踪者处理完该系统调用后，就会恢复目标进程的执行。被恢复的目标进程会一直执行下去，直到下一个系统调用。

// linux-3.10/include/linux/ptrace.h

/*
 * Ptrace flags
 *
 * The owner ship rules for task->ptrace which holds the ptrace
 * flags is simple.  When a task is running it owns it's task->ptrace
 * flags.  When the a task is stopped the ptracer owns task->ptrace.
 */

#define PT_PTRACED	0x00000001
1
2
3
4
5
6
7
8
9
10
11

// linux-3.10/include/uapi/linux/ptrace.h

#define PTRACE_TRACEME		   0
#define PTRACE_PEEKTEXT		   1
#define PTRACE_PEEKDATA		   2
#define PTRACE_PEEKUSR		   3
#define PTRACE_POKETEXT		   4
#define PTRACE_POKEDATA		   5
#define PTRACE_POKEUSR		   6
#define PTRACE_CONT		   7
#define PTRACE_KILL		   8
#define PTRACE_SINGLESTEP	   9

#define PTRACE_ATTACH		  16
#define PTRACE_DETACH		  17

#define PTRACE_SYSCALL		  24
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

// linux-3.10/include/linux/sched.h

struct task_struct {
	......
	unsigned int ptrace;
	......
	/*
	 * pointers to (original) parent process, youngest child, younger sibling,
	 * older sibling, respectively.  (p->father can be replaced with
	 * p->real_parent->pid)
	 */
	struct task_struct __rcu *real_parent; /* real parent process */
	struct task_struct __rcu *parent; /* recipient of SIGCHLD, wait4() reports */

	/*
	 * ptraced is the list of tasks this task is using ptrace on.
	 * This includes both natural children and PTRACE_ATTACH targets.
	 * p->ptrace_entry is p's link on the p->parent->ptraced list.
	 */
	struct list_head ptraced;
	struct list_head ptrace_entry;
	......
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

当一个进程被跟踪后，其struct task_struct的成员ptrace设置为PT_PTRACED，同时其parent设置为跟踪者，real_parent保留被跟踪者的真正父进程。

总结

对于应用程序的系统调用耗时可以用strace分析，对于内核中的函数调用耗时可以用ftrace分析。

参考资料

Linux 3.10

极客时间：Linux内核技术实战
Systems.Performance.Enterprise.and.the.Cloud.2nd.Edition