ハンズオンで学ぶstraceコマンド

strace is なに?

straceとは、デバッグやパフォーマンスチューニングに使わるLinuxのツールで、プロセスが発行するシステムコールを監視することができます。

システムコールとはOSの機能をアプリケーションが利用する仕組みのことで、例えばファイルへの入出力やネットワークを介した通信、新しいプロセスの立ち上げなどに使用されます。

プロセスがOSの機能をどのように利用しているのかを観察することで、障害発生時やパフォーマンスチューニング時に有用な洞察得られるケースも多いでしょう。

この記事の内容/ハンズオンのすすめ方

この記事ではハンズオン形式でstraceコマンドの使い方について学んでいきます。
環境としては、dockerが使えれば問題ないはずです。

ハンズオンの進め方としては、書いてあるシェルコマンドをそのままコピペしていけば良いです。
コマンドの出力結果も掲載していくので、この記事をただ読んでいくだけでも問題ないです。

ハンズオン編

ではハンズオンを開始します。10分ほどで終わる想定です。

CLIのパネルを2つ用意

2つのCLIの画面を用意します。
iTerm2を使っている場合はCommand+Dで画面を分割できます。

2つの画面をそれぞれパネルA、パネルBとします。
打っていくシェルコマンドで、どちらの画面で打つかを以下のように指定していきます

[パネルA]

$ echo strace_hands_on | sed 's/_/-/g'
strace-hands-on

ハンズオン用のコンテナ立ち上げ

ハンズオン用のコンテナを立ち上げます。

[パネルA]

$ docker run -it  --rm --name=strace \
 --cap-add=SYS_PTRACE \
centos:7.6.1810 /bin/bash

上記で指定しているオプション--cap-add=SYS_PTRACEについて少し補足すると、straceは内部的にはptraceというシステムコールを使用しているのですが、このオプションよってコンテナ内のプロセスがptraceを使用できるようになります。
コンテナ内プロセスがptraceを使ってホストを乗っ取る脆弱性もあるようなので、信頼できないコンテナをこのオプションを付けて起動するのは避けましょう。

パネルBをコンテナにアタッチします

[パネルB]

$ docker exec -it strace /bin/bash

strace導入

straceコマンドをインストールします。

[パネルA]

$ yum -y install strace

straceをとりあえず使ってみる

• straceは$ strace $COMMAND_NAMEで使用できます

早速straceコマンドを使用してみましょう。

[パネルA]

$ strace ls
execve("/usr/bin/ls", ["ls"], [/* 8 vars */]) = 0
brk(NULL)                               = 0xe09000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f05179f6000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=11792, ...}) = 0
mmap(NULL, 11792, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f05179f3000
close(3)                                = 0
open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320i\0\0\0\0\0\0"..., 832) = 832
.........
close(1)                                = 0
munmap(0x7f45c82a7000, 4096)            = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

上記の出力結果がlsコマンドを実行するにあたって呼び出されたシステムコールです。
lsコマンド一つでも結構な量のシステムコールが呼びされていることが分かります。
後ほど、表示されるシステムコールをうまくフィルターする方法などを紹介します。

straceの出力の見方

• straceの各行はシステムコール名、システムコールに渡す引数、システムコールの戻り値からなります。

以下のexecveシステムコールの例だと

パネルA

$ strace 2>&1 ls | head -n 1
execve("/usr/bin/ls", ["ls"], [/* 8 vars */]) = 0

execveがシステムコール名、"/usr/bin/ls", ["ls"], [/* 8 vars */]が引数、0が戻り値となります。

呼びされているシステムコールを調べる

• システムコールは$ man 2 $SYSTEM_CALL_NAMEで調べられます。

まずmanコマンドを導入します。

[パネルA]

$ yum -y --setopt=tsflags='' install man-pages man-db man

システムコールを調べたい場合はman 2に続けて、システムコールの名前を指定します。

[パネルA]

$ man 2 execve | grep DESCRIPTION -A 4
DESCRIPTION
       execve()  executes  the  program  pointed  to by filename.  filename must be either a binary exe-
       cutable, or a script starting with a line of the form:

           #! interpreter [optional-arg]

オプションの紹介

いくつか便利なオプションを紹介します。

• -c: 各システムコールの処理に占める割合を表示

[パネルA]

$ strace -c grep -r hoge /usr/bin/
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 88.83    0.001916           2      1269           read
  4.91    0.000106           0       425           fstat
  4.13    0.000089           0       458        38 openat
  2.13    0.000046           0       427           close
  0.00    0.000000           0         4           open
  0.00    0.000000           0         2           stat
  0.00    0.000000           0        71        71 lseek
  0.00    0.000000           0        12           mmap
  0.00    0.000000           0         8           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0        16           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0       419       418 ioctl
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         7           fcntl
  0.00    0.000000           0         2           getdents
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.002157                  3130       528 total

• -o: 結果をファイルに出力する

[パネルA]

$ strace -o strace_output ls 1>/dev/null ; head strace_output
execve("/usr/bin/ls", ["ls"], [/* 8 vars */]) = 0
brk(NULL)                               = 0x1490000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5e3a42f000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=11792, ...}) = 0
mmap(NULL, 11792, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5e3a42c000
close(3)                                = 0
open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320i\0\0\0\0\0\0"..., 832) = 832

• -v: 詳細を表示(システムコールに渡す引数が省略されなくなります)

[パネルA]

strace -v ls 2>&1 | head
execve("/usr/bin/ls", ["ls"], ["HOSTNAME=494a45e34aed", "TERM=xterm", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/", "SHLVL=1", "HOME=/root", "_=/usr/bin/strace"]) = 0
brk(NULL)                               = 0x1f6f000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5e320cd000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_dev=makedev(8, 1), st_ino=4210410, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=24, st_size=11792, st_atime=2018/12/04-14:39:35, st_mtime=2018/12/04-14:39:35, st_ctime=2019/05/22-11:16:27.274404000}) = 0
mmap(NULL, 11792, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5e320ca000
close(3)                                = 0
open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320i\0\0\0\0\0\0"..., 832) = 832

-s: 出力する文字数の制限を外す

[パネルA]

$ strace 2>&1 -s 1024 sh -c 'echo 123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123' \
| grep "write(1"
write(1, "123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123\n", 82123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123

-e: 出力するシステムコールをフィルタ

例えば-e trace=writeでwriteシステムコールだけ表示できます。

[パネルA]

$ strace -e trace=write echo testtest
write(1, "testtest\n", 9testtest
)               = 9
+++ exited with 0 +++

フィルタリングオプション-eの詳しい使い方についてはこのページのFilteringの説明部分を参照。

起動中のプロセスに対してstraceする

$ strace -p $PIDによって、起動中のプロセス(例えばサーバープロセス)にstraceできます。

実際に簡単なサーバーを立ててstraceをかけてみましょう。

サーバーを起動します。

[パネルA]

$ cat <<EOF > echo.py; python echo.py &
import socket, os, sys

s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
HOST, PORT = '127.0.0.1', 8080
s.bind((HOST, PORT))
s.listen(1)

def handle_request(conn):
    conn.sendall("Hi, Client! Send back what I received from you!\n")
    conn.sendall("==========================\n")
    data = conn.recv(1024)
    conn.sendall(data)
    conn.close()
    sys.exit(0)

while True:
    conn, addr = s.accept()
    newpid = os.fork()
    if newpid == 0:
        handle_request(conn)
        break
    else:
        conn.close()
        os.wait()
        continue
EOF

サーバーが動いていることを確認します。

[パネルB]

$ curl http://127.0.0.1:8080/hogehoge
Hi, Client! Send back what I received from you!
==========================
GET /hogehoge HTTP/1.1
User-Agent: curl/7.29.0
Host: 127.0.0.1:8080
Accept: */*

サーバープロセスに対してstraceします。

[パネルA]

$ PID=$(ps -aux | grep echo.py | awk '{print $2}' | head -n 1); strace -p $PID
strace: Process 217 attached
accept(3,

サーバーにリクエストを送ってみます。

[パネルB]

$ curl http://127.0.0.1:8080/hogehoge

そうすると、パネルAでサーバープロセスが呼び出したシステムコールが以下のように出力されるはずです。

accept(3, {sa_family=AF_INET, sin_port=htons(35808), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f552b26da10) = 163
close(4)                                = 0
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 163
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=163, si_uid=0, si_status=0, si_utime=1, si_stime=0} ---
accept(3,

子プロセスにもstraceする

• プロセスが子プロセスを立ち上げている場合、-fオプションを指定することで子プロセスをstraceが追跡するようになります。

上で動かしたサーバーは子プロセスを立ててリクエストを処理しています。
具体的にはnewpid = os.fork()の部分で子プロセスを生成し、子プロセスがhandle_request()の処理を行っています。
このような場合、straceが子プロセスを追跡してくれると便利ですが、-fオプションがそれを実現します。

パネルAのstraceをCtrl-Cで停止して、-fオプションを追加してstraceしてみましょう。

パネルA

$ PID=$(ps -aux | grep echo.py | awk '{print $2}' | head -n 1); strace -f -p $PID
strace: Process 137 attached
accept(3,

再びサーバーにリクエストを送ってみます。

[パネルB]

$ curl http://127.0.0.1:8080/hogehoge

パネルAで、以下のように子プロセスが行うリクエストの処理部分のシステムコールを見ることができます。

accept(3, {sa_family=AF_INET, sin_port=htons(39154), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
clone(strace: Process 172 attached
child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f552b26da10) = 172
[pid   172] set_robust_list(0x7f552b26da20, 24) = 0
[pid   137] close(4)                    = 0
[pid   137] wait4(-1,  <unfinished ...>
[pid   172] sendto(4, "Hi, Client! Send back what I rec"..., 48, 0, NULL, 0) = 48
[pid   172] sendto(4, "==========================\n", 27, 0, NULL, 0) = 27
[pid   172] recvfrom(4, "GET /hogehoge HTTP/1.1\r\nUser-Age"..., 1024, 0, NULL, NULL) = 86
[pid   172] sendto(4, "GET /hogehoge HTTP/1.1\r\nUser-Age"..., 86, 0, NULL, 0) = 86
[pid   172] close(4)                    = 0
[pid   172] rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f552aa7c5d0}, {0x7f552ad9f680, [], SA_RESTORER, 0x7f552aa7c5d0}, 8) = 0
[pid   172] close(3)                    = 0
[pid   172] exit_group(0)               = ?
[pid   172] +++ exited with 0 +++
<... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 172
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=172, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---

満足したらサーバープロセスをシャットダウンします。

[パネルB]

$ kill $(ps -aux | grep echo.py | awk '{print $2}' | head -n 1)

[おまけ] シェルからプログラムを起動する仕組み

• 一般に、プログラムの起動は、プロセスの新規作成をcloneまたはforkシステムコールで行い、プログラムの読み込みと実行をexecveシステムコールで行うことで実現されています。またリダイレクト(>)が指定された時はdup2システムコールを使って、標準出力などを置き換えます。

パネルAのシェルがプログラムを実行する様子を見るためにパネルAのシェルプロセスに対してstraceしてみましょう。

[パネルB]

$ strace -v -f -e trace=clone,execve,dup2,open  -p 1
strace: Process 1 attached

パネルAで適当なコマンドを実行すると

[パネルA]

$ sh -c 'echo test' > hoge

パネルBで以下のようにシステムコールが呼び出されているのが見えます。

clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fd453610a10) = 100
strace: Process 100 attached
[pid   100] open("hoge", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
[pid   100] dup2(3, 1)                  = 1
[pid   100] execve("/usr/bin/sh", ["sh", "-c", "echo test"], ["HOSTNAME=08cb0724c859", "TERM=xterm", "LS_COLORS=rs=0:di=01;34:ln=01;36"..., "PATH=/usr/local/sbin:/usr/local/"..., "PWD=/", "SHLVL=1", "HOME=/root", "_=/usr/bin/sh"]) = 0
.....

cloneとexecveが、それぞれ「新しいプロセスの生成」と「プログラムの実行」を担っているシステムコールです。また、open("hoge", ...) = 3によってhogeファイルをファイルディスクリプタ3として開き、それをdup2(3, 1)で標準出力(=1)にセットしています。

• cloneはプロセスを生成します。仕組みや振る舞いはforkと似ていて、親プロセスをコピーすることによって子プロセスがつくられます。ファイルディスクリプタもコピーされるので、例えば子プロセスで標準出力に書き出すと、親プロセスの標準出力にも書き出されることになります。参考: man-pagesのcloneとfork

• execveは現在プロセスが実行しているプログラムを、パスで指定されたプログラムで置き換えて実行を開始します。プログラムとして指定できるのは、実行可能なバイナリ、もしくは#! path_to_interpreterで始まるスクリプトファイルです。参考: man-pagesのexecve

• dup2は第一引数のファイルディスクリプタを第二引数のファイルディスクリプタにコピーします。つまり、第二引数のファイルディスクリプタ対する操作は第一引数のファイルディスクリプタへの操作と同一になります。第二引数のファイルディスクリプタが使用済みだった場合、使用前にクローズされます。参考: man-pagesのdup2

• [補足] clone/forkが親プロセスをコピーするのに高速な理由

• cloneやforkはプロセスを複製をすることで新しいプロセスを生成しますが、複製はcopy on writeという仕組みを利用しているので高速です。

cloneやforkは親プロセスをコピーして子プロセスを作りますが、その時親プロセスが使用しているメモリもコピーされるのを考えると、パフォーマンス的に問題ないのかどうかが気になる人もいると思います。
実はメモリのコピーは高速に行えて、どうやっているのかというと、最初はコピーしたふりをしといて、本当にコピーするのは必要になるまでギリギリまで先延ばししているのです。
プロセスのメモリは、仮想メモリの仕組みによって、物理メモリを4kBほどの区分に分けたページが各プロセスに割り当てられていて、どのページがどのプロセスを所有しているか管理するページテーブルによって、論理アドレスから物理アドレスへの変換が行われます。
forkやcloneでプロセスのメモリをコピーするときは最初はこのページテーブルだけコピーします。参照だけコピーしているといっても良いかも知れません。
各ページの値が同一である限り、ページを親子間で使い回すことに問題はありませんが、メモリの値が同一でなくなる、つまりメモリへの書き出しを行う際には実際にページをコピーする必要が出てきます。
このように、最初は参照(ページテーブル)だけコピーし、実際のメモリ(=ページ)のコピーは書き出しが行われるまで先延ばしする仕組みのことをcopy on writeといって、これによってforkやcloneは高速にプロセスの複製を行えます。

お片付け

コンテナを落とす

[パネルA]

$ exit

imageの消去

パネルA

$ docker image rm centos:7.6.1810

まとめ

• 調査したいプロセスがあったら以下を打つ

$ strace -f -v -o strace_output -s 1024 -p $PID

• システムコールの詳細はmanコマンドで調べる

$ man 2 $SYSTEM_CALL_NAME

straceの詳しい使い方についてはこちらやこのqiita記事を参考