本連載では第一線のPerlハッカーが回替わりで執筆していきます。今回のハッカーはMobageオープンプラットフォームの開発に携わっている横江直輔（zentooo）さんで，テーマは「Perlプログラマのためのstrace入門」です。

strace──システムコールレベルでのデバッグツール

straceとは何か

straceとは，manによれば「システムコールとシグナルをトレースする（ためのツール）」です。システムコールとシグナルはいずれも重要なAPIですが，本稿ではアプリケーション内で発行されているシステムコールをトレースするためのツールとしてのstraceに注目します。

システムコールとは何か

straceでシステムコールの流れをトレースするにあたりシステムコールとは何かという話題を避けては通れませんので，ここで簡単に説明しておきます。

Linuxを始めとする現代のOSでは，私たちユーザが作ったアプリケーションが直接ディスクを読み書きしたり，ネットワーク通信を行うことは，一部の例外を除いてありません。アプリケーションのコードだけを見ると外部のリソースを直接操作しているように思える部分も，実際はアプリケーションはOSに「こういう処理をしてね」とお願いし，OSに働いてもらって，その結果を受け取るという動作をしています。この「こういう処理をしてね」とOSにお願いする機能を提供しているのがシステムコールです。ユーザが作成したプログラムに対してOSが公開しているAPIがシステムコールである，とも言えます。また，我々の書いたアプリケーションが低いレベルにおいて「何をできるか」の限界はOSが定めている，とも言えます。

たとえば，多くのWebアプリケーションで行われている「ログをファイルに書く」という操作では，open(2)，lseek(2)，write(2)，close(2)などのシステムコールが呼ばれます。なお，一般に各種システムコールを表記する際にはwrite(2)のようにmanのセクション番号を付けることが多いです。本稿でも一般名詞・動詞などと区別するためにこの表記を採用します。

すべてのシステムコールがそうというわけではありませんが，「アプリケーションはOSの提供するAPIの上で，さまざまなリソースを借りたうえで処理を行っている」というモデルで考えると，しっくりくる部分が多いかと思います。アプリケーションで必要になる「借りる」操作をシステムコールに対応させていくつか挙げてみると，次のようになります。

自分と同じプロセスを複製したい

→fork(2)を使って新しいプロセスを「借りる」

メモリを確保したい

→brk(2)を使ってメモリ空間を「借りる」

ネットワーク通信がしたい

→socket(2)を使ってネットワークスタックの機能を「借りる」

ディスクに書き込みたい

→open(2)を使ってディスクデバイスを「借りる」

なお，本稿では各種システムコールのリファレンス的な意味における詳細な説明は行いません。必要に応じて手元のLinux環境でmanを参照するか，『ふつうのLinuxプログラミング』（注1），『The Linux Programming Interface』（注2）などを参照してください。

注1）

青木峰郎著『ふつうのLinuxプログラミング──Linuxのしくみから学べるgccプログラミングの王道』SBクリエイティブ，2005年

注2）

Michael Kerrisk, The Linux Programming Interface: A Linux and UNIX System Programming Handbook, No Starch Press, 2011

straceの使い方

本節では，straceのコマンドラインツールとしての使い方，出力結果，オプションなどについて説明します。

straceはCentOSやDebian GNU/Linuxなど業務で使われることの多いLinuxディストリビューションではデフォルトでインストールされていると思いますが，もしシステム管理の都合上インストールしていないなどの場合は，システム管理者にかけあってインストールしてもらうなどしてください。

最もシンプルな使い方

straceの最もシンプルな使い方は以下です。$cmdの部分には実行可能なコマンドが入ると考えてください。

$ strace $cmd

たとえば$cmdがcat hogeであった場合，上記コマンドの実行結果の出力は次のようになります（hogeというファイルには「This is hoge」という文字列が書かれているものとします）。

execve("/bin/cat", ["cat", "hoge"], [/* 24 vars */]) = 0
...
（中略）
...
open("hoge", O_RDONLY)                  = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=13, ...}) = 0
read(3, "This is hoge\n", 32768)        = 13
write(1, "This is hoge\n", 13)          = 13
read(3, "", 32768)                      = 0
close(3)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0);                          = ?

なんとなく「cat hogeがやっていそうな内容だなぁ」ということがおわかりいただけるかと思います。この場合，strace経由で起動したコマンドに対してstraceはattachしており，そのコマンドが発行したシステムコールを見ることができます。

straceは，最も基本的な情報として各システムコールの引数，戻り値を表示します。各システムコールへの引数は見たままの値であり，戻り値は各行の右側に=付きで表記されています。たとえば上記の例において，最初のopen(2)の引数はhogeおよびO_RDONLYであり，その戻り値は3となります。

既存プロセスへのattach

特にWebアプリケーションのデバッグ目的の場合，すでに立ち上がっているプロセスのトレースを行いたい場合のほうが多いと思います。その場合は次のようにコマンドラインオプションを指定します（注3）。

$ strace -p $pid

表示される内容は先ほどの例とほぼ同じなので，出力例は割愛します。事実上，straceを利用する多くの場面では-p付きで実行することになります。

注3）

-pオプション付きでのstraceの実行には環境によってroot権限あるいはsudoが必要ですが，本稿ではそれらの表記は省略します。

straceのコマンドラインオプション

ここでは，straceのよく使うコマンドラインオプションについて解説します。

-ttオプション──タイムスタンプの表示

-ttオプションを指定することで，各システムコールにおおむねどのくらいの時間がかかっているかをマイクロ秒単位で表示できます。

「おおむね」と書いたのは，-ttオプションで表示されるのは「あるシステムコールを実行した時点での時間」であり，それらの差分を見ることで「おおむね」の実行時間を知ることができるという意味においてです。たとえば次の出力例で2行目のioctlと1行目のacceptの行の左端に表示されている時間（ともに太字）の差分を取ると4.4秒くらいになりますが，これは「acceptを実行し，ブロックして，リクエストを受け付け，次にioctlを実行する」までの時間です。これを「実行時間」と呼ぶのはいささか乱暴なので，筆者は「差を見るとおおよその実行時間がわかる」と言うことにしています。

$ strace -p $pid -tt
15:44:56.351227 accept(4, {sa_family=AF_INET, sin_
port=htons(59812), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
15:45:00.771790 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x
7fffce10ff10) = -1 EINVAL (Invalid argument)
15:45:00.771872 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illeg
al seek)
15:45:00.771937 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x
7fffce10ff10) = -1 EINVAL (Invalid argument)
15:45:00.771972 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illeg
al seek)
15:45:00.772001 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
15:45:00.772242 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR)
15:45:00.772324 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
15:45:00.772378 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
15:45:00.772509 read(5, "GET / HTTP/1.0\r\nHost: xxx-xxxxx
x"..., 131072) = 308

straceには-tt以外にも時間表示用のオプションがありますが，-ttが最もヒューマンリーダブルかつある程度時間の粒度が細かく，またアプリケーションのアクセスログなどと付き合わせる際にも使いやすい出力になるので，筆者はいつも-ttを使っています。

-sオプション──表示する文字列の最大長の指定

-sオプションで数値を指定することにより，read(2)やwrite(2)に渡されているバッファの中身を省略せずに見ることができます（-ttオプションの出力例の最後の行を見ると「...」となっている部分がありますが，そこがまさに省略された部分です）。このオプションは，strace を使って実際のHTTP 通信の中身や，memcachedなどのミドルウェアとの通信の中身を詳しく見たい場合に利用します。

次の出力例では，-ttオプションの出力例では省略されていたHTTPヘッダの内容がすべて表示されていることがわかります。

$ strace -p $pid -tt -s $strsize
16:33:42.649421 accept(4, {sa_family=AF_INET, sin_port=htons(60
543), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
16:33:45.630289 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffc
e10ff10) = -1 EINVAL (Invalid argument)
16:33:45.630360 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal se
ek)
16:33:45.630399 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffc
e10ff10) = -1 EINVAL (Invalid argument)
16:33:45.630432 lseek(5, 0, SEEK_CUR) = -1 ESPIPE (Illegal se
ek)
16:33:45.630461 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
16:33:45.630564 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR)
16:33:45.630607 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:33:45.630658 setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
16:33:45.630788 read(5, "GET / HTTP/1.0\r\nHost: xxx-xxxxx
xx.xxxxxx.jp\r\nX-Forwarded-Host: xxx-xxxxxxx.xxxxxx.jp\r\
nX-Forwarded-Server: xxx-xxxxxxx.xxxxxx.jp\r\nX-For
warded-For: 10.4.40.179\r\nX-Forwarded-HTTPS: on\r\nConnec
tion: close\r\nUser-Agent: curl/7.24.0 (x86_64-apple-darwin12.
0) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.5\r\n
Accept: */*\r\n\r\n", 131072) = 308

利用上の注意

筆者の経験上，straceでattachすることによって著しいパフォーマンスの劣化などが起こることはありません。ただし，サービスの本番環境などでサーバプロセスにattachするような場合は，事前にシステム管理者などに問題ないかを確認してから慎重に利用することをお勧めします。