Perl Hackers Hub

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

(1)こちら⁠2)こちらから。

strace実践編─⁠─Webアプリケーションは思ったとおりに動かない

最後はstraceの実践編です。

Perlで書いたWebアプリケーションの動作の妥当性は、どうやって担保すればよいでしょうか。もちろんユニットテストである程度の担保はできますし、Selenium WebDriverなどを使って実際にブラウザを立ち上げてサービス自体の動作を自動チェックしている人も多いと思います。また、自動テストをしたうえで、やはり最後は実機で動作を見るという慎重な人もいると思います。

これらはいずれも有効なのですが、どちらかと言うとプログラムの動作に対する外側からのチェックであるため、⁠memcachedにデータを効率良くキャッシュしているつもりが、実は頻繁にデータベースにアクセスが飛んでいた」⁠Redisに都度接続でTCPコネクションを張っていたつもりが、張りっぱなしになっていた」などの下回りの障害につながりかねない問題に気づくことができません。

こういった問題は得てして、気づいたときにはすでに本番で障害が発生していることが多いです。できる限り開発環境でのシステム監視などで事前に発見したいところですが、開発環境と本番環境のサーバスペックや、Webアプリケーションで立ち上げているプロセスの総数(ホストをまたいだ合計値)などが異なっているような場合には、なかなか難しいものです。

開発環境などであらかじめさらっとstraceの結果を見ておくと、上記のような問題を事前に発見できる可能性があります。

Perlで作られたWebアプリケーションで陥りがちなパターン

昨今の現場はさまざまなミドルウェアが使われているので一概には言えませんが、個人的な感覚としては、Cache::Memcached::Fastなどのクライアント側でコンシステントハッシュ法を使ってスケーリングさせるライブラリを用いてmemcachedにアクセスしている場合に、straceで観測できる次のような下回りの問題が起こりやすいようです。

  • 接続先のノード数をあまり気にせず多数のkeyに対してget_multiやset_multiを実行するコードがデプロイされた結果、リクエスト中で全ノードへの接続・再接続が発生するようになり応答が劣化する
  • アプリケーション側で生成しているkeyの値が間違っている、あるいはアプリケーション間でずれており、キャッシュを活用しているつもりが実は常にデータベースにフォールバックしている
  • 思ったよりキャッシュヒット率が低く、実はデータベースにフォールバックしている

「俺ならそんなことはやらかさない」と思う人もいるかと思いますが、実際にstraceでmemcachedへのアクセスからのMySQLへのアクセスなどの流れを見ると、思ったとおりのアクセスパターンになっていなかったということはよくあります。特に後者2つは、アプリケーションの見かけ上の動作としては問題なく、かつリクエストが少ない間は顕在化しないため発見が難しいです。しかし本番環境などへの展開前にちょっと時間をとってstraceの結果を眺めてみることで気づける確率が高いです。

これはあくまで憶測ですが、上記のような問題が起こりやすいのは、次のような理由からと考えています。

  • ライブラリ側でしれっとコンシステントハッシュ法による分割が行われるため、利用者側であまり接続先のノード数(Cache::Memcached::Fastの場合はnewで渡すserversの数)を意識しないことが多い
  • 同様の理由で、それぞれのノードに対してどういうタイミングでTCPコネクションが張られるかを意識しないことが多い

以降では、実際の現場でstraceを使うことにより問題発見・問題解決に至った実例を2つ紹介します。

実例1:epollを使っているつもりが、select(2)を使っていた

AnyEventはPerlでイベント駆動なアプリケーションを書く場合によく使われるモジュールです。通常、Linux上でAnyEventを利用したコードを書く場合は、I/O多重化のバックエンドとしてepoll_*系のAPIが利用されることを期待します。実際にはAnyEventをuseしたうえでそのバックエンドの一つであるEVがインストールされている(require可能な状態になっている)場合のみLinux上でepollが使われるのですが、本番環境で投入されているコンポーネントにEVがインストールされていなかったため、フォールバックした結果としてselect(2)が使われている、という問題がありました。

これはいささか極端な例ですが、外部から見るとどちらのAPIが使われているかはパッとはわからないところでも、straceでattachすれば一発でわかります。結論としてはselectが使われていることで問題が起こっていたわけではなかったのですが、そのままにしておくのもあとあとよくないのでEVをインストール、デプロイして修正を行いました。

実例2:memcachedへのgetが連続で空振りしていた

あるWeb APIのレスポンスが、あるリリース以後に急に劣化するという事件がありました。具体的には、今までのレスポンスタイムに対して約180ミリ秒の遅延が上乗せされる状態になりました。リリースを境に平均的に180ミリ秒もレスポンスタイムが劣化するのは異常です。該当のリリースにはmemcached関連のモジュール(Cache::Memcached::Fastのラッパのようなもの)のバージョンアップが含まれており、とある人が「これじゃね?」と言っていたのでおもむろにstraceしてみると、次のようなシーケンスが流れてきました[5]⁠。

22:45:34.517703 sendmsg(6, {msg_name(0)=NULL, msg_iov(4)=[
{"get", 3}, {" cache_local:", 13}, {"keyword_list:1", 14},
{"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL
) = 32
22:45:34.537967 sendmsg(6, {msg_name(0)=NULL, msg_iov(4)=[
{"get", 3}, {" cache_local:", 13}, {"keyword_list:1", 14},
{"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL
) = 32
22:45:34.558936 sendmsg(6, {msg_name(0)=NULL, msg_iov(4)=[
{"get", 3}, {" cache_local:", 13}, {"keyword_list:1", 14},
{"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL
) = 32
22:45:34.579275 sendmsg(6, {msg_name(0)=NULL, msg_iov(4)=[
{"get", 3}, {" cache_local:", 13}, {"keyword_list:1", 14},
{"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL
) = 32
22:45:34.587428 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=
[{"get", 3}, {" cache_remote1:", 14}, {"keyword_list:1",
14}, {"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOS
IGNAL) = 33
22:45:34.608296 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=
[{"get", 3}, {" cache_remote1:", 14}, {"keyword_list:1", 1
4}, {"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSI
GNAL) = 33
22:45:34.628673 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=
[{"get", 3}, {" cache_remote1:", 14}, {"keyword_list:1", 1
4}, {"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOS
IGNAL) = 33
22:45:34.649146 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=
[{"get", 3}, {" cache_remote1:", 14}, {"keyword_list:1", 1
4}, {"\r\n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSI
GNAL) = 33
22:45:35.135129 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=
[{"get", 3}, {" cache_remote2:", 16}, {"bsf_err", 7}, {"\r\
n", 2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 28
22:45:35.155516 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=[{
"get", 3}, {" cache_remote2:", 16}, {"bsf_err", 7}, {"\r\n",
2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 28
22:45:35.176027 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=[{
"get", 3}, {" cache_remote2:", 16}, {"bsf_err", 7}, {"\r\n",
2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 28
22:45:35.196453 sendmsg(11, {msg_name(0)=NULL, msg_iov(4)=[{
"get", 3}, {" cache_remote2:", 16}, {"bsf_err", 7}, {"\r\n",
2}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 28

見たところ、まったく同じネームスペース、keyに対するgetが各4回ずつ繰り返されているようです。

ここで種明かしをすると、くだんのモジュールの更新差分は「set、getなどがミスった場合に最大3回リトライを行う」という機能の追加でした。⁠ミスった」はいわゆるキャッシュミスではなく、memcachedにリクエストを送る経路上のパケットロスなどを指しています。このときのモジュールの改修もそれに対するものだったのですが、Cache::Memcached::Fastのgetメソッドは「キャッシュミスだろうがネットワーク上の問題だろうが、あるいは瞬間的にmemcachedが落ちていようが、失敗時はすべてundefが返る」という挙動をするため、実際にはキャッシュミスとそのほかのエラーを区別できません。

そのため、上記はいずれも実際には単にキャッシュミスが起こっていただけなのですが、それに対して正直にもリトライ処理が発動してしまっていた、というのがことの真相でした。この場合は各リトライを行うまでの時間間隔を20ミリ秒に設定していたため、3種類のキャッシュにアクセスしていずれも3回のリトライが起こった結果として、180ミリ秒の遅延が起こったというわけです。

このアプリケーションおよびモジュールについては、

  • ほぼ毎回キャッシュミスになっているようなキャッシュはそもそも意味がない
  • データベースのデータのキャッシュとして使われているデータならば、getをリトライする意味はそもそもない(低確率で起こるエラーなら、普通のキャッシュミスと同様に単にデータベースにフォールバックすればよいため)

という問題の合わせ技が起こっていたのですが、いずれもstraceで確かめることにより挙動が確定したため、あまり悩むことなく対策できました。

以下に、修正前と修正後のコードを示します。ただし、あくまで記事向けのサンプルコードであるためオリジナルのコードと比べ多くの省略・改変が加えられている点に留意してください。

修正前
package Memcached::Retry;

use Sub::Retry qw/retry/;

for my $method (qw/get set add delete remove replace
prepand append cas gets incr decr/) {
    no strict 'refs';
    *{$method} = sub {
        my ($self, @args) = @_;

        # $self->{max_retry} の値はデフォルトでは3
        my $ret = retry(
            $self->{max_retry} + 1,
            $self->{retry_interval},
            sub {
                $self->{memcached_client}->$method(@args);
            },
            sub {
                my $do_retry = defined $_[0] ? 0 : 1;
                return $do_retry;
            }
        );
        return $ret;
    };
}
修正後
package Memcached::Retry;

use Sub::Retry qw/retry/;

for my $method (qw/get set add delete remove replace
prepand append cas gets incr decr/) {
    no strict 'refs';
    *{$method} = sub {
        my ($self, @args) = @_;

        # $self->{max_retry_write} の値はデフォルトでは3
        # $self->{max_retry_read} の値はデフォルトでは0
        my $max_retry =
          ($method eq "get" || $method eq "gets") ?
          $self->{max_retry_read} :
          $self->{max_retry_write};
        my $ret = retry(
            $self->{max_retry} + 1,
            $self->{retry_interval},
            sub {
                $self->{memcached_client}->$method(@args);
            },
            sub {
                my $do_retry = defined $_[0] ? 0 : 1;
                return $do_retry;
            }
        );
        return $ret;
    };
}

まとめ

今回は、主にアプリケーション内で発行されているシステムコールをトレースするためのツールであるstraceを紹介しました。本文中で少し触れましたが、あらゆるツールがそうであるように、straceは万能ツールではなく適した場面と適さない場面があります。適した場面では、手軽なデバッグツールとして機能してくれるでしょう。またデバッグ目的に役立つのはもちろんですが、筆者個人の思うところとしては、straceを使うことで普段自分が触っているWebアプリケーションの気持ちがわかるようになり、普段はあまり意識しない少し低めのレイヤに興味を持って開発を行えるようになるという、ある種の自己教育的なメリットがあります。これはエンジニアとしての一般論ですが、普段業務で関わりのあるレイヤだけでなく、少し異なるレイヤに目を向けることで、新たな発見があることも多いかと思います。

さて、次回の執筆者はkarupaneruraさんで、テーマは「Perlによるデータベースプログラミング入門」です。お楽しみに。

おすすめ記事

記事・ニュース一覧