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

# strace is なに?

[strace](https://ja.wikipedia.org/wiki/Strace)とは、デバッグやパフォーマンスチューニングに使わるLinuxのツールで、プロセスが発行するシステムコールを監視することができます。

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

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

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

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

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

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

## CLIのパネルを2つ用意

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

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

```sh:[パネルA]
$ echo strace_hands_on | sed 's/_/-/g'
strace-hands-on
```

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

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


```sh:[パネルA]
$ docker run -it  --rm --name=strace \
 --cap-add=SYS_PTRACE \
centos:7.6.1810 /bin/bash
```
上記で指定しているオプション`--cap-add=SYS_PTRACE`について少し補足すると、straceは内部的には[`ptrace`というシステムコール](http://man7.org/linux/man-pages/man2/ptrace.2.html)を使用しているのですが、このオプションよってコンテナ内のプロセスが`ptrace`を使用できるようになります。
コンテナ内プロセスが`ptrace`を使って[ホストを乗っ取る脆弱性](https://sil.hatenablog.com/entry/why-container-is-secure)もあるようなので、信頼できないコンテナをこのオプションを付けて起動するのは避けましょう。

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

```sh:[パネルB]
$ docker exec -it strace /bin/bash
```

## strace導入

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


```sh:[パネルA]

$ yum -y install strace
```

## straceをとりあえず使ってみる
* straceは`$ strace $COMMAND_NAME`で使用できます

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


```sh:[パネル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`](http://man7.org/linux/man-pages/man2/execve.2.html)システムコールの例だと

```sh:パネル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`コマンドを導入します。

```sh:[パネルA]
$ yum -y --setopt=tsflags='' install man-pages man-db man
```

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


```sh:[パネル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`: 各システムコールの処理に占める割合を表示

```sh:[パネル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`: 結果をファイルに出力する

```sh:[パネル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`: 詳細を表示(システムコールに渡す引数が省略されなくなります)

```sh:[パネル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`: 出力する文字数の制限を外す

```sh:[パネルA]
$ strace 2>&1 -s 1024 sh -c 'echo 123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123' \
| grep "write(1"
write(1, "123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123\n", 82123aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa123
```

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

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



```sh:[パネルA]
$ strace -e trace=write echo testtest
write(1, "testtest\n", 9testtest
)               = 9
+++ exited with 0 +++
```

フィルタリングオプション`-e`の詳しい使い方については[このページ](http://man7.org/linux/man-pages/man1/strace.1.html)のFilteringの説明部分を参照。

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

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

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

サーバーを起動します。

```sh:[パネル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
```

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

```sh:[パネル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`します。

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

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

```sh:[パネルB]
$ curl http://127.0.0.1:8080/hogehoge
```

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

```sh
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`してみましょう。

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

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

```sh:[パネルB]
$ curl http://127.0.0.1:8080/hogehoge
```

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

```sh
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} ---
```

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

```sh:[パネルB]
$ kill $(ps -aux | grep echo.py | awk '{print $2}' | head -n 1)
```

## [おまけ] シェルからプログラムを起動する仕組み
* 一般に、プログラムの起動は、プロセスの新規作成を[clone](http://man7.org/linux/man-pages/man2/clone.2.html)または[fork](http://man7.org/linux/man-pages/man2/fork.2.html)システムコールで行い、プログラムの読み込みと実行を[execve](http://man7.org/linux/man-pages/man2/fork.2.html)システムコールで行うことで実現されています。またリダイレクト(`>`)が指定された時は[dup2](http://man7.org/linux/man-pages/man2/dup.2.html)システムコールを使って、標準出力などを置き換えます。

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

```sh:[パネルB]
$ strace -v -f -e trace=clone,execve,dup2,open  -p 1
strace: Process 1 attached
```

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

```sh:[パネル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](http://man7.org/linux/man-pages/man2/clone.2.html)と[fork](http://man7.org/linux/man-pages/man2/fork.2.html)

* `execve`は現在プロセスが実行しているプログラムを、パスで指定されたプログラムで置き換えて実行を開始します。プログラムとして指定できるのは、実行可能なバイナリ、もしくは`#! path_to_interpreter`で始まるスクリプトファイルです。参考: man-pagesの[execve](http://man7.org/linux/man-pages/man2/fork.2.html)

* `dup2`は第一引数のファイルディスクリプタを第二引数のファイルディスクリプタにコピーします。つまり、第二引数のファイルディスクリプタ対する操作は第一引数のファイルディスクリプタへの操作と同一になります。第二引数のファイルディスクリプタが使用済みだった場合、使用前にクローズされます。参考: man-pagesの[dup2](http://man7.org/linux/man-pages/man2/dup.2.html)
* 
## [補足] clone/forkが親プロセスをコピーするのに高速な理由
* `clone`や`fork`はプロセスを複製をすることで新しいプロセスを生成しますが、複製はcopy on writeという仕組みを利用しているので高速です。

`clone`や`fork`は親プロセスをコピーして子プロセスを作りますが、その時親プロセスが使用しているメモリもコピーされるのを考えると、パフォーマンス的に問題ないのかどうかが気になる人もいると思います。
実はメモリのコピーは高速に行えて、どうやっているのかというと、最初はコピーしたふりをしといて、本当にコピーするのは必要になるまでギリギリまで先延ばししているのです。
プロセスのメモリは、仮想メモリの仕組みによって、物理メモリを4kBほどの区分に分けた[ページ](https://ja.wikipedia.org/wiki/%E4%BB%AE%E6%83%B3%E8%A8%98%E6%86%B6#%E3%83%9A%E3%83%BC%E3%82%B8%E3%83%B3%E3%82%B0%E6%96%B9%E5%BC%8F)が各プロセスに割り当てられていて、どのページがどのプロセスを所有しているか管理する[ページテーブル](https://ja.wikipedia.org/wiki/%E3%83%9A%E3%83%BC%E3%82%B8%E3%83%86%E3%83%BC%E3%83%96%E3%83%AB)によって、論理アドレスから物理アドレスへの変換が行われます。
`fork`や`clone`でプロセスのメモリをコピーするときは最初はこのページテーブルだけコピーします。参照だけコピーしているといっても良いかも知れません。
各ページの値が同一である限り、ページを親子間で使い回すことに問題はありませんが、メモリの値が同一でなくなる、つまりメモリへの書き出しを行う際には実際にページをコピーする必要が出てきます。
このように、最初は参照(ページテーブル)だけコピーし、実際のメモリ(=ページ)のコピーは書き出しが行われるまで先延ばしする仕組みのことを[copy on write](https://ja.wikipedia.org/wiki/%E3%82%B3%E3%83%94%E3%83%BC%E3%82%AA%E3%83%B3%E3%83%A9%E3%82%A4%E3%83%88)といって、これによって`fork`や`clone`は高速にプロセスの複製を行えます。

# お片付け

コンテナを落とす

```sh:[パネルA]
$ exit
```
imageの消去

```sh:パネルA
$ docker image rm centos:7.6.1810
```
# まとめ

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

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

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

```sh
$ man 2 $SYSTEM_CALL_NAME
```

straceの詳しい使い方については[こちら](http://man7.org/linux/man-pages/man1/strace.1.html)や[このqiita記事](https://qiita.com/hana_shin/items/a03150552e2f70994248)を参考