第29回　Perlプログラマのためのstrace入門ーWebアプリケーションをシステムコールレベルでデバッグしよう（2）

前回の（1）はこちらから。

Webサーバが呼ぶシステムコール

（2）では、PSGI（Perl Web Server Gateway Interface）互換のアプリケーションサーバとしてStarmanやStarletなどを使っている場合に、それらのモジュールが処理する部分でのシステムコールについて解説します。

通常のアプリケーション開発では、「⁠Starman/StarletやFCGIなどWebサーバとして動く部分」はあまり意識せず「自分が開発しているアプリケーション部分（Webアプリケーションフレームなども含む⁠）⁠」に意識が集中していることが多いでしょう。しかし、Webアプリケーションが発行するシステムコールという観点に立つなら、それらの間に区別はありません。straceを使ってトレースを行った場合も当然、アプリケーション内でのレイヤを問わず、時系列順に発行されたシステムコールが表示されます。

一般に、Perlで書かれたWebアプリケーションをstraceすると次のようなシーケンスが繰り返し見られます[4]⁠。

accept(4, {sa_family=AF_INET, sin_port=htons(49150), sin_a
ddr=inet_addr("127.0.0.1")}, [16]) = 5
（中略）
read(5, "GET / HTTP/1.0\r\nHost: xxx-xxxxxx"..., 131072) = 308
（中略）
write(5, "HTTP/1.1 200 OK\r\nDate: Sun, 10 A"..., 2218) = 2218
close(5)                                  = 0
accept(4,

Webサーバはaccept(2)で待ち受け、リクエストが到着するまでブロックし、リクエストを受け付けた時点で処理がアプリケーション側に戻ります。上記のシーケンスでは、1回目のacceptの戻り値として5が返っていますが、この値がクライアント側のソケットを表すファイルディスクリプタとなります。

「UNIXではあらゆるものがファイルである」という思想めいた言葉を目にしたことがある人も多いかと思います。Linuxにおいても同様に、ディスクなどへのRead/WriteやネットワークソケットへのRead/Writeは、ファイルディスクリプタへのread(2)、write(2)として表現されます。すなわち、HTTPクライアントからのリクエストを読み込み、レスポンスを返すということは、クライアント側のソケットを表すファイルディスクリプタに対してread(2)、write(2)を行うのと同義になります。上記の例では、5を引数にread(2)やwrite(2)を呼び出し、最後にclose(2)を呼んでレスポンスの終わりとし、またaccept(2)を呼び出して次のリクエストを待ち受ける、という一連の流れを見ることができます。

利用しているWebサーバ実装によっては、これらのシステムコールの前段にselect(2)が挟まっていたり、epoll_wait(2)が絡んでいたりと、異なる処理シーケンスでリクエストを処理している場合もありますが、Webアプリケーションがリクエストを受けてレスポンスを返すまでの最も基本的な形はこれになります。

Webアプリケーションで注目すべきシステムコール

前節では「HTTPリクエストを受け付け、HTTPレスポンスを返す」という、Webアプリケーションとして最も本質的な部分のシーケンスに触れました。ただ実際のアプリケーションをstraceしてデバッグやパフォーマンスチューニングを行う場合に最も気になるのは、やはりその中間にある自分たちのサービスのために書かれた処理の部分です。

非常にざっくり分類すると、リクエスト／レスポンスの間に行われる処理は次の3つになります。

（a）ネットワークソケットを開き、読み取り、書き込む
（b）ファイルを開き、読み取り、書き込む
（c）リクエストの内容、および上記2つによって得られたデータに基づいて計算を行う

Perlで書かれたWebアプリケーションでは、データを永続化するためにMySQLやPostgreSQL、またはいわゆるNoSQLに類するデータベースを利用し、それら永続化データのキャッシュとしてmemcached、Redisなどを用いることが多いでしょう。それらミドルウェアへのアクセスはネットワークを経由して行われるため、straceから見ると（a）として観測されます。

また、リクエストの途中でログを書いたり、ファイルキャッシュにアクセスしたり、特定の設定ファイルを読み込むなどの操作は（b）として観測されます。

本節の以降では、（⁠a）（⁠b）の操作で利用されるシステムコールと、それに沿ったstraceの内容の読み方を解説します。（⁠c）については、（⁠a）などに比べると問題が起こりにくく、また問題があった場合もstraceによる調査ではなくほかのアプローチをとったほうがよい部分なので、本稿では触れません。

ソケットに関するシステムコール

TCPソケットを利用してネットワークアクセスを行っているWebアプリケーションをstraceした場合、次のようなシーケンスが見られます。

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 10
fcntl(10, F_SETFL, O_RDONLY)            = 0
fcntl(10, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl(10, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(10, {sa_family=AF_INET, sin_port=htons(3306), sin_
addr=inet_addr("10.0.0.1")}, 16) = -1 EINPROGRESS (Operati
on now in progress)
fcntl(10, F_SETFL, O_RDWR)              = 0
poll([{fd=10, events=POLLIN|POLLPRI}], 1, 4000) = 1 ([{fd=
10, revents=POLLIN}])
setsockopt(10, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0
\0\0\0\0\0\0\0\0\0", 16) = 0
setsockopt(10, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0
\0\0\0\0\0\0\0\0\0", 16) = 0
setsockopt(10, SOL_IP, IP_TOS, [8], 4) = 0
setsockopt(10, SOL_TCP, TCP_NODELAY, [1], 4) = 0
setsockopt(10, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
poll([{fd=10, events=POLLIN}], 1, 4000) = 1 ([{fd=10, reve
nts=POLLIN}])
read(10, "G\0\0\0\n5.1.61-community-log\0o"..., 16384) = 75
write(10, "3\0\0\1\217\242\2\0\0\0\0@!\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0"..., 55) = 55
(以下、read, write, pollの繰り返し)

どういうシステムコールが発行されるかはクライアントライブラリの実装に依存します（たとえば上記のstraceは、DBI/DBD::mysqlを利用してMySQLにアクセスを行った場合のものです⁠）⁠。

より一般化すると次の流れになります。

socket(2)でソケットを作成
connect(2)でTCPコネクションを確立
write(2)/read(2)の繰り返し（pollなどを挟む場合もあり）
close(2)でTCPコネクションをクローズ（持続的接続を行わない場合）

straceとミドルウェアへのネットワークアクセス

特定のシーケンスがどのミドルウェアに対するアクセスかを判別するうえで最も簡単な方法は、connect(2)の第2引数の部分に書いてあるsin_portを見ることです。たとえば上記シーケンスにおいては、6行目の「sin_port=htons(3306)」の部分が相当します。各ミドルウェアをどのportで立ち上げているかは実運用環境しだいですが、この場合筆者はMySQLのデフォルト値である3306をそのまま使っていることを知っているので、「⁠sin_port=htons(3306)」を見た時点でMySQLへのアクセスであることが確定できます。

TCPソケットに関するシステムコールをstraceでトレースすることにより、次のような確認が行えます。

想定していないIPアドレスに対して接続が行われていないか
TCPコネクションが想定どおりのタイミングで確立・切断されているか
想定していないデータを受信・送信していないか

たとえば例として使ったアプリケーションでは、straceの結果をかなりあとまで追わないと該当のソケットに対するclose(2)の呼び出しは現れません。このアプリケーションの場合は「一度張ったTCPコネクションは1リクエスト中は使い回し、HTTPレスポンスを返す直前にまとめてMySQLへの接続を切断する」というポリシーであるため、MySQLへのアクセスごとに毎回close(2)が呼び出されていないのは想定どおりの動作です。

逆にMySQLへのアクセスが発生するたびに都度TCPコネクションを接続・切断をするようなポリシーのアプリケーションで毎回close(2)が呼ばれていない場合は、何らかの形で切断処理が漏れてしまっていることになります。

ファイル操作に関するシステムコール

ファイル操作周りについては、straceによって次のようなシーケンスが観測できます。

open("/tmp/xxx/cache", O_RDONLY) = 11
ioctl(11, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffb7de9cb0) =
-1 ENOTTY (Inappropriate ioctl for device)
lseek(11, 0, SEEK_CUR)                  = 0
fstat(11, {st_mode=S_IFREG|0644, st_size=41, ...}) = 0
fcntl(11, F_SETFD, FD_CLOEXEC)          = 0
read(11, "[{\"value\":\"10.0.0.1\",\"weight"..., 41) = 41
close(11)

ネットワークアクセスに比べるとファイルI/Oはそこまで問題になることは多くないですが、複数プロセス間でデータを共有するためにファイルキャッシュを利用しているアプリケーションや、ログを自動でローテートするようなモジュールを利用しているアプリケーションにおいて、想定どおりの動作をしているかを見る際にstraceが便利に使える場合があります。

straceとその他ツールの使い分け

ここまで見てきたとおり、straceはプロセスの挙動を調査し、デバッグなどを行う際にとても有用です。しかしすべてのツールがそうであるように、straceにも適した場面と適さない場面があります。たとえば、

（a）Perlレイヤでの各モジュール・メソッドの実行時間をトレースしたい
（b）MySQL、memcachedにアクセスする際にかかっている時間を定点観測したい
（c）ネットワークレイヤで起こっている問題（TCPにおけるSYNの再送など）を調査したい

というような個別のケースに関しては、それぞれstraceよりも向いたツールがあります。

Devel::NYTProf――Perlレイヤにおけるパフォーマンス計測ツール

たとえば（a）のケースに関しては、straceはあくまで発行されているシステムコールに沿った調査しかできません。そのため自作Perlモジュールで非常に効率の悪いアルゴリズムが実装されている、あるいは無限ループやそのほか無駄な制御フローが実行されているというような場合に問題個所を特定するには不向きです。この場合は、Perlレイヤにおける有名なパフォーマンス計測ツールDevel::NYTPro（f 以下NYTProf）を仕込んで計測する手法のほうが適しているでしょう。

Devel::KYTProf――ネットワーク周りのパフォーマンス計測ツール

（b）のケースに対応する、Perlでネットワークアクセス周りの処理時間の定点観測を行うツールとしては、Devel::KYTPro（f 以下KYTProf）が有名です。実際のユースケースにおいて、機能としてstraceと最も被りが大きいのはKYTProfになると思います。筆者はついついstraceのほうを使ってしまうので、実はそこまで真面目にKYTProfを利用したことはないですが、

（一時的なトレースではなく）アプリケーションの各種ミドルウェアとの通信時間を定点観測したい
常時起きている問題ではなく、確率的に起こる問題を捕まえたい

という場合には、アプリケーションに仕込んで長期的にログを取ることができるKYTProfのほうが適していると考えます。

tcpdump、tshark――トランスポート層以下のトレース

straceでトレースできるのはシステムコールとシグナルのみであるため、当然ながら（c）のケースのようなトランスポート層以下の問題解決には使えません。そういった場合はおとなしくtcpdumpなどの有名なツールを使うか、あるいは（筆者もごく最近存在を知ったのですが）wiresharkと同等のフィルタリング機能をコマンドラインから使えるtsharkを使ったほうがよいです。筆者は日常的に駆使しているわけではありませんが、複数のネットワークレイヤにまたがったフィルタリングをリアルタイムで行うことのできるtsharkは、使いこなせればとても有用なツールになり得ると思います。

なぜstraceを使うか

ここまでで、「⁠じゃあ、なんでstraceを使うの？頑張ってstraceの結果を読むよりKYTProfのほうが簡単だしよくない？」といった感想を持った人もいるかと思います。筆者の考えるstraceの利点は以下です。

事前に仕込みを行う必要がなく、見たいときにすぐ見られる
特定のミドルウェアアクセスに特化したものではないので、取り逃しがない
Linuxのプロセスなら何でもトレースできるので、開発言語を問わず使える
ソースが手元にない（あるいはパッと手に入らない）バイナリでも使える

Perlを使った開発が前提である場合は後者2つの利点にそこまで恩恵が感じられないかと思いますが、ツールの使い方を覚えるのにあまり時間を投じたくない筆者のような人間としては、いったん覚えれば言語を問わず使えるツールは魅力的です。

＜続きの（3）はこちら。＞