性能优化工具-strace

概述

使用 strace 查看系统调用统计可以帮助你分析一个进程的行为，特别是它在运行时进行的系统调用

原理

strace 使用 ptrace 系统调用追踪目标进程

当被跟踪的进程

用法

基本用法

• 追踪指定的pid

strace -p 1

• 直接启动追踪一个新进程

strace bash

• -o输出到文件

strace bash -o strace.out

• -f 追踪子进程

strace -f <command>

• -t ,-r 显示时间

strace -t <command> # 显示时间戳
strace -r <command> # 显示相对事件

系统调用统计

-c 计算每个系统调用和报告的时间、调用和错误

# strace -c ls
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         7           read
  0.00    0.000000           0         4           write
  0.00    0.000000           0        23           close
  0.00    0.000000           0        22           fstat
  0.00    0.000000           0        30           mmap
  0.00    0.000000           0         5           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         3           brk
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000           0       147        17 total

• % time：该系统调用占用的时间百分比。
• seconds：该系统调用总共占用的时间。
• usecs/call：每个系统调用平均耗时（微秒）。
• calls：该系统调用被调用的次数。
• errors：该系统调用的错误次数。
• syscall: 系统调用名称

通过这个命令，可以简单排查一些系统系统调用耗时过长，或者频率过高的问题

过滤

-e 一个限定表达式，用于修改要跟踪哪些事件或如何跟踪它们。

trace=set：指定要跟踪的系统调用集。set 可以是以下之一：

• none : 不追踪任何系统调用
• file：所有与文件相关的系统调用。
• process：所有与进程管理相关的系统调用。
• network：所有与网络相关的系统调用。
• signal：所有与信号相关的系统调用。
• ipc：所有与进程间通信相关的系统调用。
• desc：所有与文件描述符相关的系统调用。
• memory：所有与内存管理相关的系统调用。
• all：所有系统调用。

signal=set：指定要跟踪的信号集。

• set 可以是信号名称或信号编号的列表，如 signal=SIGINT,SIGTERM 或 signal=2,15。
• signal=all 跟踪所有信号。

status=set：跟踪特定状态的系统调用

• status=successful  成功的系统调用
• status=failed 失败的系统调用

fault=set：跟踪所有导致错误的系统调用。

• fault=open 追踪所有open的 错误系统调用

write 过滤写相关的系统调用

read 过滤读相关的系统调用

示例:

• 过滤系统调用

# 追踪open、openat、create系统调用
strace -e trace=open,openat,creat bash

• 只追踪信号

例如这行命令不追踪系统调用，但是追踪所有的信号

# strace -e trace=none -e signal=all bash

(base) deepwzh@LAPTOP-LQE5ODGS:~$ --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=314209, si_uid=1002} ---

(base) deepwzh@LAPTOP-LQE5ODGS:~$ --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
--- SIGINT {si_signo=SIGINT, si_code=SI_USER, si_pid=314209, si_uid=1002} ---

• 只追踪失败的系统调用

# strace -e status=failed ls
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
statfs("/sys/fs/selinux", 0x7ffd883acf40) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffd883acf40)      = -1 ENOENT (No such file or directory)
access("/etc/selinux/config", F_OK)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_IDENTIFICATION", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/locale/C.UTF-8/LC_MEASUREMENT", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)= -1 ENOENT (No such file or directory)

用例

获取进程的网络请求内容

strace -t -e trace=network curl http://example.com -o debug.txt

上述命令利用过滤network请求，并打印了时间戳, 可以在debug.txt得到下述内容，这个将有助于排查网络问题

19:23:25 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
19:23:25 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
19:23:25 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
19:23:25 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
19:23:25 socket(AF_INET6, SOCK_DGRAM, IPPROTO_IP) = 5
19:23:25 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
19:23:25 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
19:23:25 setsockopt(5, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
19:23:25 setsockopt(5, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
19:23:25 setsockopt(5, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
19:23:25 connect(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("93.184.215.14")}, 16) = -1 EINPROGRESS (Operation now in progress)
19:23:25 getsockname(5, {sa_family=AF_INET, sin_port=htons(47683), sin_addr=inet_addr("192.168.2.106")}, [128 => 16]) = 0
19:23:26 socket(AF_INET6, SOCK_STREAM, IPPROTO_TCP) = 6
19:23:26 setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0
19:23:26 setsockopt(6, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
19:23:26 setsockopt(6, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
19:23:26 setsockopt(6, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
19:23:26 connect(6, {sa_family=AF_INET6, sin6_port=htons(80), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "2606:2800:21f:cb07:6820:80da:af6b:8b2c", &sin6_addr), sin6_scope_id=0}, 28) = -1 ENETUNREACH (Network is unreachable)
19:23:26 getsockname(6, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, [128 => 28]) = 0
19:23:26 getsockopt(5, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
19:23:26 getsockname(5, {sa_family=AF_INET, sin_port=htons(47683), sin_addr=inet_addr("192.168.2.106")}, [128 => 16]) = 0
19:23:26 getpeername(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("93.184.215.14")}, [128 => 16]) = 0
19:23:26 getsockname(5, {sa_family=AF_INET, sin_port=htons(47683), sin_addr=inet_addr("192.168.2.106")}, [128 => 16]) = 0
19:23:26 getpeername(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("93.184.215.14")}, [128 => 16]) = 0
19:23:26 getsockname(5, {sa_family=AF_INET, sin_port=htons(47683), sin_addr=inet_addr("192.168.2.106")}, [128 => 16]) = 0
19:23:26 sendto(5, "GET / HTTP/1.1\r\nHost: example.co"..., 74, MSG_NOSIGNAL, NULL, 0) = 74
19:23:27 recvfrom(5, "HTTP/1.1 200 OK\r\nAccept-Ranges: "..., 102400, 0, NULL, NULL) = 1614
<!doctype html>
<html>
<head>
    <title>Example Domain</title>
    <meta charset="utf-8" />
</head>

<body>
<div>
    <h1>Example Domain</h1>
    <p>This domain is for use in illustrative examples in documents. You may use this
    domain in literature without prior coordination or asking for permission.</p>
    <p><a href="https://www.iana.org/domains/example">More information...</a></p>
</div>
</body>
</html>
+++ exited with 0 +++
19:23:27 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=321806, si_uid=1002, si_status=0, si_utime=0, si_stime=3 /* 0.03 s */} ---

输出后台进程的标准输出

当使用nohup & 放在后台执行而未指定日志输出时，往往会丢失 他的输出

可以使用

# strace -e trace=write -p <pid>
write(1, "HelloWorld\n", 11HelloWorld
)            = 11
+++ exited with 0 +++

实现对后台进程的输出捕获，可以自行配合脚本得到更可读的内容

总结

• 程序使用任何操作系统的功能，都要通过系统调用进行，strace 就是用来剖析程序内部是怎么使用系统调用的，可以通过指定pid或者直接执行命令的方式进程
• strace也可以追踪特定进程收到的信号 使用 -e signal=set 实现
• 可以使用 -e 一些常用过滤表达式来优化分析效率, 比如只输出失败的，只看网络的等等
• 可以通过 -c 输出系统调用周期内的统计信息分析