2.3. Important strace Options

2.3. Important strace Options

This section is not meant to be a replacement for the strace manual. The strace manual does a good job of documenting issues and options for strace but does not really describe when to use the various options. The focus of this section is to briefly describe the important strace options and when to use them.

本节不打算取代 strace 手册。strace 手册很好地记录了 strace 的问题和选项, 但并不真正描述何时使用各种选项。本节的重点是简要描述重要的 strace 选项以及何时使用它们。

2.3.1. Following Child Processes

By default strace only traces the process itself and not any child processes that may be spawned. There are several reasons why you may need or want to trace all of the child processes as well, including:

默认情况下, strace 只跟踪进程本身, 而不是任何可能生成的子进程。您可能需要或希望跟踪所有子进程, 其中包括:

• Tracing the activity of a command line shell.
• 跟踪shell命令行的活动。
• Tracing a process that will create a daemon process that will continue to run after the command line tool exits.
• 跟踪在命令行工具退出后创建继续运行的守护进程的进程。
• Tracing inetd or xinetd to investigate problems relating to logging on to a system or for tracing remote connections to a system (an example of this is included later in this chapter).
• 跟踪 inetd 或 xinetd 以调查与登录系统或跟踪系统远程连接有关的问题 (本章后面将包括此示例)。
• Some processes spawn worker processes that perform the actual work while the parent process manages the worker process pool.
• 某些进程生成在父进程管理辅助进程池时执行实际工作的工作进程。

To trace a process and all of its children, use the -f flag. Tracing with -f will have no effect if the process does not fork off any children. However, the output will change once a child is created:

若要跟踪进程及其所有子进程, 请使用-f 标志。如果进程不创建任何子进程, 则-f将无效。但是, 一旦创建了子进程, 输出就会更改:

rt_sigprocmask(SIG_SETMASK, [INT], [INT], 8) = 0

rt_sigprocmask(SIG_BLOCK, [INT], [INT], 8) = 0

rt_sigprocmask(SIG_SETMASK, [INT], [INT], 8) = 0

rt_sigprocmask(SIG_BLOCK, [CHLD], [INT], 8) = 0

fork()                                  = 24745

                                                        [pid 14485] setpgid(24745, 24745 <unfinished ...>

[pid 24745] gettimeofday( <unfinished ...>

[pid 14485] <... setpgid resumed> )     = 0

 

In particular, the system calls are prefixed with a process ID to distinguish the various processes being traced. The grep utility can then be used to separate the strace output for each process ID.

特别是, 系统调用前缀为进程 ID, 以区分所跟踪的各个进程。然后, grep可以用来分隔每个进程 ID 的 strace 输出。

Note: As a rule of thumb, always use the -f switch unless you specifically want to exclude the output from the child processes. 注意: 作为一个经验法则, 始终使用-f 开关, 除非您特别想排除子进程的输出。

2.3.2. Timing System Call Activity

The strace tool also can be used to investigate some types of performance problems. In particular, the timed tracing features can provide information about where a process is spending a lot of time.

strace 还可用于调查某些类型的性能问题。特别是, 定时跟踪功能可以提供有关进程花费大量时间的信息。

Be very careful not to make incorrect assumptions about where the time is spent. For example, the -t switch will add a timestamp (time of day) to the strace output, but it is a timestamp between the system call entry times. In other words, subtracting two timestamps gives time for the first system call and the user code that is run between the two system calls.

要非常小心, 不要对时间的花费做出错误的假设。例如,-t 将向 strace 输出添加一个时间戳 (某天中的某一时间), 但它是系统调用进入时间之间的时间戳。换言之, 两个时间戳的差是第一个系统调用和在两个系统调用之间运行的用户代码的时间。

There are two other ways to include a timestamp: -tt (time of day with microseconds) and -ttt (number of seconds since the epoch with microseconds).

还有两种方法可以包括时间戳:-tt (以微秒计某天中的时间) 和-ttt (以微秒计从纪元的秒数)。

Note: The -tt option is usually the best option to capture a timestamp. It includes the time of day with microseconds. 注意: tt 选项通常是捕获时间戳的最佳选项。它以微秒计某天中的时间。

 

If you’re interested in getting the time between system calls, you can use the -r switch:

如果您对在系统调用之间的时间感兴趣, 可以使用-r 开关:

                                                        ion 235% strace -r main

0.000000 execve("./main", ["main"], [/* 64 vars */]) = 0

0.000801 fcntl64(0, F_GETFD)       = 0

0.000090 fcntl64(1, F_GETFD)       = 0

0.000055 fcntl64(2, F_GETFD)       = 0

0.000052 uname({sys="Linux", node="ion", ...}) = 0

0.000305 geteuid32()               = 7903

0.000038 getuid32()                = 7903

0.000038 getegid32()               = 200

0.000037 getgid32()                = 200

0.000076 brk(0)                    = 0x80a3ce8

0.000048 brk(0x80a3d08)            = 0x80a3d08

0.000040 brk(0x80a4000)            = 0x80a4000

0.000054 brk(0x80a5000)            = 0x80a5000

0.000058 open("/tmp/foo", O_RDONLY) = -1 ENOENT (No such file or directory)

0.000092 _exit(5)                  = ?

 

Again, keep in mind that this is the time between two system call entries and includes the time for the system call and the user code. This usually has limited usefulness.

同样, 请记住, 这是两个系统调用进入之间的时间, 包括系统调用和用户代码的时间。它的用处有限。

A more useful method of timing actual system calls is the -T switch. This provides the actual time spent in a system call instead of the time between system calls. It is slightly more expensive because it requires two timestamps (one for the system call entry and one for the system call exit) for each system call, but the results are more useful.

一个更有用的计算实际系统调用的方法是T开关。这提供了在系统调用中花费的实际时间, 而不是系统调用之间的时间。由于每个系统调用需要两个时间戳 (一个用于系统调用项, 一个用于系统调用退出), 因此它的开销略高一些, 但结果更有用。

Code View: Scroll / Show All

                                                        ion 249% strace -T main

execve("./main", ["main"], [/* 64 vars */]) = 0

fcntl64(0, F_GETFD)                     = 0 <0.000016>

fcntl64(1, F_GETFD)                     = 0 <0.000012>

fcntl64(2, F_GETFD)                     = 0 <0.000012>

uname({sys="Linux", node="ion", ...})   = 0 <0.000013>

geteuid32()                             = 7903 <0.000012>

getuid32()                              = 7903 <0.000012>

getegid32()                             = 200 <0.000011>

getgid32()                              = 200 <0.000012>

brk(0)                                  = 0x80a3ce8 <0.000012>

brk(0x80a3d08)                          = 0x80a3d08 <0.000011>

brk(0x80a4000)                          = 0x80a4000 <0.000011>

brk(0x80a5000)                          = 0x80a5000 <0.000012>

open("/tmp/foo", O_RDONLY)              = -1 ENOENT (No such file or directory) <0.000019>

_exit(5)                                = ?

 

The time spent in the system call is shown in angle brackets after the system call (seconds and microseconds).

系统调用所用的时间在系统调用后的尖括号中显示 (秒和微秒)。

Another useful way to time system calls is with the -c switch. This switch summarizes the output in tabular form:

计算系统调用所用时间的另一个有用的方法是使用-c 开关。此开关以表格形式汇总输出:

 ion 217% strace -c main

 execve("./main", ["main"], [/* 64 vars */]) = 0

 % time   seconds  usecs/call calls    errors   syscall

 ______ __________ _________ ________ ________ ______________

 40.00     0.000030     30         1         1 open

 25.33     0.000019      6         3           fcntl64

 16.00     0.000012      3         4           brk

  5.33     0.000004      4         1           uname

  4.00     0.000003      3         1           getuid32

  4.00     0.000003      3         1           getegid32

  2.67     0.000002      2         1           getgid32

  2.67     0.000002      2         1           geteuid32

______  __________ _________ ________ ________ ______________

100.00     0.000075               13         1 total

 

It can also be useful to time both the difference between system call entries and the time spent in the system calls. With this information, it is possible to get the time spent in the user code between the system calls. Keep in mind that this isn’t very accurate unless there is a considerable amount of time spent in the user code. It also requires writing a small script to parse the strace output.

同时, 还可以使用系统调用进入与系统调用所用时间的差异。使用此信息, 可以获取在系统调用之间用户代码所花费的时间。请记住, 这不是非常准确的, 除非有相当多的时间花在用户代码。它还需要编写一个小脚本来分析 strace 输出。

Code View: Scroll / Show All

ion 250% strace -Tr main

  0.000000 execve("./main", ["main"], [/* 64 vars */]) = 0

  0.000931 fcntl64(0, F_GETFD)       = 0 <0.000012>

  0.000090 fcntl64(1, F_GETFD)       =  0 <0.000022>

  0.000060 fcntl64(2, F_GETFD)       =  0 <0.000012>

  0.000054 uname({sys="Linux", node="ion", ...}) = 0 <0.000014>

  0.000307 geteuid32()               =  7903 <0.000011>

  0.000040 getuid32()                =  7903 <0.000012>

  0.000039 getegid32()               =  200 <0.000011>

  0.000039 getgid32()                =  200 <0.000011>

  0.000075 brk(0)                    =  0x80a3ce8 <0.000012>

  0.000050 brk(0x80a3d08)            =  0x80a3d08 <0.000012>

  0.000043 brk(0x80a4000)            =  0x80a4000 <0.000011>

  0.000054 brk(0x80a5000)            =  0x80a5000 <0.000013>

  0.000058 open("/tmp/foo", O_RDONLY) =  -1 ENOENT (No such file or directory) <0.000024>

  0.000095 _exit(5)                  =  ?

Note: Some of the time spent may not be due to a system call or user code but may be due to the scheduling behavior of the system. The program may not execute on a CPU for a small period of time on a busy system because other programs are competing for CPU time. 注意: 花费的一些时间可能不是由于系统调用或用户代码造成的, 而是由于系统的调度行为。由于其他程序正在争夺 cpu 时间, 程序在繁忙的系统上可能会在 cpu 上执行很长的时间。

2.3.3. Verbose Mode

By default, strace does not include all of the information for every system call. It usually provides a good balance between enough information and too much. However, there are times when more information is required to diagnose a problem. The verbose option -v tells strace to include full information for system calls such as stat or uname.

默认情况下, strace 不包括每个系统调用的所有信息。它通常在足够的信息和太多之间提供良好的平衡。但是, 有时需要更多的信息来诊断问题。详细选项 v 告诉 strace 包含系统调用 (如统计或 uname) 的完整信息。

Code View: Scroll / Show All

ion 251% strace -v main

execve("./main", ["main"], [/* 64 vars */]) = 0

fcntl64(0, F_GETFD)                     = 0

fcntl64(1, F_GETFD)                     = 0

fcntl64(2, F_GETFD)                     = 0uname({sysname="Linux", nodename="ion", release="2.4.19-64GB-SMP", version="#1 SMP Mon Oct 21 18:48:05

                                                        UTC 2002", machine="i686"}) = 0

geteuid32()                             = 7903

getuid32()                              = 7903

getegid32()                             = 200

getgid32()                              = 200

brk(0)                                  = 0x80a3ce8

brk(0x80a3d08)                          = 0x80a3d08

brk(0x80a4000)                          = 0x80a4000

brk(0x80a5000)                          = 0x80a5000

open("/tmp/foo", O_RDONLY)              = -1 ENOENT (No such file or directory)

_exit(5)                                = ?

 

Notice that the uname system call is fully formatted with all information included. Compare this to the preceding examples (such as the strace of the statically linked program):

请注意, uname 系统调用已完全格式化为包含的所有信息。将此与前面的示例 (如静态链接程序的 strace) 进行比较:

uname({sys="Linux", node="ion", ...})   = 0

 

Another verbose feature is -s, which can be useful for showing more information for the read and write system calls. This option can be used to set the maximum size of a string to a certain value.

另一个冗长的功能是 s, 这对于显示读写系统调用的更多信息非常有用。此选项可用于将字符串的最大大小设置为特定值。

Code View: Scroll / Show All

                                                        ion 687% strace dd if=strace.strace of=/dev/null bs=32768 |& tail -15 | head -10

write(1, "DATA, 30354, 0xbfffe458, [0x2e6f"..., 32768) = 32768

read(0, "ETFD, FD_CLOEXEC\", 30) = 30\nptra"..., 32768) = 32768

write(1, "ETFD, FD_CLOEXEC\", 30) = 30\nptra"..., 32768) = 32768

read(0, "ed) —\nrt_sigprocmask(SIG_BLOCK"..., 32768) = 32768

write(1, "ed) —\nrt_sigprocmask(SIG_BLOCK"..., 32768) = 32768

read(0, ") && WSTOPSIG(s) == SIGTRAP], 0x"..., 32768) = 7587

write(1, ") && WSTOPSIG(s) == SIGTRAP], 0x"..., 7587) = 7587

read(0, "", 32768)                              = 0

write(2, "7+1 records in\n", 157+1 records in

)        = 15

 

Of course, this shows very little information about the contents that were read or written by dd. In many cases, an investigation requires more or all of the information. Using the switch -s 256, the same system call trace will show 256 bytes of information for each read/write:

当然, 这显示了 dd 读或写的很少信息。在许多情况下, 调查需要更多或全部信息。使用开关 -s 256, 对于相同的系统调用跟踪将显示每读/写的256字节信息:

 

Code View: Scroll / Show All

ion 688% strace -s 256 dd if=strace.strace of=/dev/null bs=32768 |&

tail -15 | head -10 write(1,  "DATA, 30354, 0xbfffe458, [0x2e6f732e]) =

0\nptrace(PTRACE_PEEKDATA, 30354, 0xbfffe45c, [0xbfff0031]) =

0\nwrite(2, \"open(\\\"/home/wilding/sqllib/lib/l\"..., 54) =

54\nptrace(PTRACE_SYSCALL, 30354, 0x1, SIG_0) = 0\n— SIGCHLD (Child

exited) —\nrt_sigprocmask(SI"..., 32768) = 32768 read(0, "ETFD, FD_CLOEXEC\", 30) = 30\nptrace(PTRACE_SYSCALL,

30354, 0x1, SIG_0) = 0\n— SIGCHLD (Child exited) —

\nrt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\nwait4(-1,

[WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =

30354\nrt_sigprocmask(SIG_BLOCK, ["..., 32768) = 32768 write(1, "ETFD, FD_CLOEXEC\", 30) = 30\nptrace(PTRACE_SYSCALL,

30354, 0x1, SIG_0) = 0\n— SIGCHLD (Child exited) —

\nrt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\nwait4(-1,

[WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =

30354\nrt_sigprocmask(SIG_BLOCK, ["..., 32768) = 32768 read(0, "ed) —\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE TERM],

NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX, [0x4]) =

0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]) =

0\nptrace(PTRACE_PEEKUSER, 30354, 4*EBX, [0x1]) =

0\nptrace(PTRACE_PEEKUSER, "..., 32768) = 32768 write(1, "ed) —\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE

TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX,

[0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]) =

0\nptrace(PTRACE_PEEKUSER, 30354, 4*EBX, [0x1]) =

0\nptrace(PTRACE_PEEKUSER, "..., 32768) = 32768 read(0, ") && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) = 30354\n—

SIGCHLD (Child exited) —\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT

PIPE TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX,

[0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]"...,

32768) = 7587 write(1, ") && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =

30354\n— SIGCHLD (Child exited) —\nrt_sigprocmask(SIG_BLOCK, [HUP

INT QUIT PIPE TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354,

4*ORIG_EAX, [0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX,

[0xffffffda]"..., 7587) = 7587 read(0, "", 32768) write(2, "7+1 records in\n", 157+1 records in" )        = 15

 

The amount of information shown in the strace output here is pretty intimidating, and you can see why strace doesn’t include all of the information by default. Use the -s switch only when needed.

strace 输出中显示的信息量相当惊人, 您可以看到为什么 strace 在默认情况下不包含所有信息。仅在需要时使用-s 开关。

2.3.4. Tracing a Running Process

Sometimes it is necessary to trace an existing process that is running, such as a Web daemon (such as apache) or xinetd. The strace tool provides a simple way to attach to running processes with the -p switch:

有时需要跟踪正在运行的现有进程, 如 Web 守护程序 (如 apache) 或 xinetd。strace 提供了一种使用-p 开关访问运行进程的简单方法:

ion 257% strace -p 3423

 

Once attached, both the strace tool and the traced process behave as if strace ran the process off of the command line. Attaching to a running process establishes a special parent-child relationship between the tracing process and the traced process. Everything is pretty much the same after strace is attached. All of the same strace options work whether strace is used to trace a program off of the command line or whether strace is used to attach to a running process.

一旦附加, strace 和被跟踪进程的行为就好像 strace 从命令行运行进程一样。附加到正在运行的进程将在跟踪过程和被跟踪过程之间建立特殊的父子关系。Strace附加到被跟踪进程后, 下面的操作与直接运行strace差不多。所有的 strace 选项都适用于 strace 从命令行跟踪程序, 和使用 strace 附加到正在运行的进程。