Perl Hackers Hub

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

この記事を読むのに必要な時間:およそ 4 分

実例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;
    };
}
注5)
このstraceはある程度アタリをつけたあとのものなので,-eオプションを使ってトレースするシステムコールをCache::Memcached::Fastが内部的に利用するsendmsg(2)だけに絞っています。また,一部の文字列は値を実際のものから変えています。

まとめ

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

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

著者プロフィール

横江直輔(よこえなおすけ)

意識の低いエンジニア。仕事ではPerlとかJavaScriptとか書いたり。個人AndroidアプリをScalaでちょこちょこ作っていたが,最近Google Playのアカウントを剥奪された。

App Storeにも一個アプリを出したが放置状態。Objective-C忘れました。

Blog:http://zentoo.hatenablog.com/