再現させる

bulkneetsツールを使ったが、Ubuntu Intrepid (2.6.27-11-server)では再現せず。RHEL5(2.6.18-128.el5)では再現した。もうちょい色々な環境で試してみる必要が有りそう。

エラーメッセージからの追跡

stanakaさんの以下の発言より。

* http://twitter.com/stanaka/status/21037070317

以下のメッセージが出るらしい。

[err] event_queue_remove: 0x15ea9d88(fd 30) not on queue 8

event.c event_queue_remove()の先頭部分でのメッセージ。

void
event_queue_remove(struct event_base *base, struct event *ev, int queue)
{
        if (!(ev->ev_flags & queue))
                event_errx(1, "%s: %p(fd %d) not on queue %x", __func__,
                           ev, ev->ev_fd, queue);

queue “8″ は、event.hによるとEVLIST_ACTIVE.

#define EVLIST_ACTIVE   0x08

event_queue_removeをEVLIST_ACTIVEで呼び出している箇所は複数有る。が、ev_flags & EVLIST_ACTIVE をチェックせずに呼び出しているのは2箇所、event_reinit()とevent_process_active()になる。

event_reinit()はmemcachedからは呼び出されている所が無いので、自ずとevent_process_activeの以下の箇所になる。

        for (ev = TAILQ_FIRST(activeq); ev; ev = TAILQ_FIRST(activeq)) {
                if (ev->ev_events & EV_PERSIST)
                        event_queue_remove(base, ev, EVLIST_ACTIVE);
                else
                        event_del(ev);

activeqには入っているが、ev_flagsにEVLIST_ACTIVEが立っていない条件が成立しうるらしい。

activeqにいれているのは、一箇所、event_queue_insert()になる。ただし、入れる前にかならずev_flagsにEVLIST_ACTIVEは立てている。

ということで、他の場所でev_flagsを弄ってしまっているかメモリ破壊を疑いたい。

ひとまず前者を疑うと、ev_flagsを変更しているのは event_queue_insert(), event_queue_remove(), event_queue_set() になる。insert, removeに関しては問題ないので、疑うとすればset()。この関数が既存eventに対してevent_del()せずにいきなり呼ばれたりするのが怪しそう。

が、memcachedにはそんな箇所は無いので有った。メッセージが出る時の、ev->ev_flagsの値が欲しい…座礁ed.

現象からの追跡

event_base_loop()中のevent_haveevents(base)がfalse、つまりbase->event_countが0になっているらしい。

これは通常は有り得ない、というのもlisten用(新規コネクション受付用)のeventが常に有るはずなので。event_countが減算されるのは、event_queue_remove()。通常は、event_del()から呼ばれる。

となるとlisten用のeventまで消えてしまうのは、event_del()するかメモリ破壊ぐらいしか無い。listen用のeventをevent_del()しているのは、コネクションが溢れたときに呼ばれる以下の関数。

void do_accept_new_conns(const bool do_accept) {
    conn *next;

    for (next = listen_conn; next; next = next->next) {
        if (do_accept) {
            update_event(next, EV_READ | EV_PERSIST);
            if (listen(next->sfd, settings.backlog) != 0) {
                perror("listen");
            }
        }
        else {
            update_event(next, 0);
            if (listen(next->sfd, 0) != 0) {
                perror("listen");
            }
        }
    }
    ... snip ...
}

コネクションが溢れたときには、do_acceptがfalseになっている。update_event()では、event_del() => event_add()しているが、このevent_add() が失敗しているんじゃないかと予想(メモリ破壊じゃなければ)。そうすると、event_countが0になるシナリオは作れる。

このupdate_event()の失敗を捕まえられればなあ…やっぱ次はなんとか手元で再現させる事を考えよう。

mixiの件について、nealさんから情報を貰ったので数時間調査してみた。というのも、うちの製品でもlibevent(evhttp)をリクエスト処理に使っているので、これにバグが有ると非常に困る。

• Nealさんのつぶやき

ひとまず、libevent-1.3b, libmemcached-1.4.4をビルドする。memcachedは、-cで同時接続数を制限できる。で、この同時接続数というのは、実はファイルディスクリプタの数を制限する事で達成されている。memcached.cの以下の部分。

    /*
     * If needed, increase rlimits to allow as many connections
     * as needed.
     */
    if (getrlimit(RLIMIT_NOFILE, &rlim) != 0) {
        fprintf(stderr, "failed to getrlimit number of files\n");
        exit(EX_OSERR);
    } else {
        int maxfiles = settings.maxconns;
        if (rlim.rlim_cur < maxfiles)
            rlim.rlim_cur = maxfiles;
        if (rlim.rlim_max < rlim.rlim_cur)
            rlim.rlim_max = rlim.rlim_cur;
        if (setrlimit(RLIMIT_NOFILE, &amp;rlim) != 0) {
            fprintf(stderr, "failed to set rlimit for open files. Try running as root or requesting smaller maxconns value.\n");
            exit(EX_OSERR);
        }
    }

mixiでは30kコネクションだが、それをエミュレーションするのは辛い。ということで環境を擬似的に再現するために、以下のように変更してディスクリプタ数を非常に小さい値に設定して、クライアント側でそれ以上の並列数を指定してみる事にした。

        int maxfiles = settings.maxconns;
        rlim.rlim_cur = maxfiles;
        rlim.rlim_max = maxfiles;
        if (setrlimit(RLIMIT_NOFILE, &rlim) != 0) {
            fprintf(stderr, "failed to set rlimit for open files. Try running as root or requesting smaller maxconns value.\n");
            exit(EX_OSERR);
        }

これで、並列数を32などに制限できる。

$ ./memcached -c 32 -t 4 -v -v -v

次に、libmemcached付属のツールmemslapで負荷をかける

$ memslap -s localhost:11211 --threads=1 --concurrency=32 -S 1s

サーバーが固まります。以下のようなメッセージと共に。

event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory
event_add: No such file or directory

conn_new()のここ。

    if (event_add(&c->event, 0) == -1) {
        if (conn_add_to_freelist(c)) {
            conn_free(c);
        }
        perror("event_add");
        return NULL;
    }

まずはボトムアップだ！という事でstrace -f で調査してみた所、以下のような結果。

[pid 10655] write(2, "<31 new auto-negotiating client "..., 43<31 new auto-negotiating client connection
) = 43
[pid 10655] epoll_ctl(13, EPOLL_CTL_MOD, 31, {EPOLLIN|EPOLLOUT, {u32=31608592, u64=31608592}}) = -1 ENOENT (No such file or directory)
[pid 10655] write(2, "event_add: No such file or direc"..., 37event_add: No such file or directory
) = 37
[pid 10655] write(2, "Can\'t listen for events on fd 31"..., 33Can't listen for events on fd 31
) = 33   

EPOLL_CTL_ADDされていないディスクリプタにEPOLL_CTL_MODしようとしているらしい。これはmemcachedか、libeventが不正な状態を持っちゃってこうなってるんだろう。

memcachedはlibeventと変な形で密結合していて、上に登っていくのが厳しい。イベントベースなのも有るし。

という事で今度はトップダウンでソースから。サーバーでディスクリプタが足りなくなるのは、一箇所、accept(2)の所。

            if ((sfd = accept(c->sfd, (struct sockaddr *)&addr, &addrlen)) == -1) {
                if (errno == EAGAIN || errno == EWOULDBLOCK) {
                    /* these are transient, so don't log anything */
                    stop = true;
                } else if (errno == EMFILE) {
                    if (settings.verbose > 0)
                        fprintf(stderr, "Too many open connections\n");
                    accept_new_conns(false);
                    stop = true;
                } else {
                    perror("accept()");
                    stop = true;
                }
                break;
            }

この、accept_new_conns(false)が怪しい。ひとまずこれをコメントアウトした所、クライアント側は固まらなくなった。この先は、listen用のコネクションをepoll contextから外して新しいコネクションを受け付けないようにしている。

この辺りのクリーンアップ処理がおかしいのかも？と調査中….

    conn *next;
    for (next = listen_conn; next; next = next->next) {
        if (do_accept) {
            update_event(next, EV_READ | EV_PERSIST);
            if (listen(next->sfd, settings.backlog) != 0) {
                perror("listen");
            }
        }
        else {
            update_event(next, 0);
            if (listen(next->sfd, 0) != 0) {
                perror("listen");
            }
        }
    }

あとは、ニールさんが”base_event_loopからなぜか抜けてしまいます”とおっしゃっているのだが、これが再現出来ていない。ループを抜けるとサーバーが終了してしまうはずなのだが、手元ではサーバーが固まるのみ。

ふーむー。

blogはご無沙汰中です。3月で大学を卒業して、社会人生活を満喫しています。頭の切り替えが楽になった気がします。

最近は古橋さんが中心となってやっている、MessagePackというプロジェクトに少しコミットしています。同じような目的のプロジェクトとして、Google ProtocolBuffer・Apache Thrift・Apache Avroなどが有ります。簡単に言うと、JSONより速くてコンパクトなシリアライズ/デシリアライズライブラリです。

• MessagePackのサイト

MessagePackは非常に安定して十分にプロダクトでも使えるレベルなので、是非使ってみて下さい。C/C++ライブラリを用いて、毎月数億回ぐらいは(de)serializeを行なっていますが、非常に安定して稼働しています。

僕は特に、MessagePackを使用したRPC(Remote Procedure Call)の仕組みの部分にコミットしようと思っています。MessagePack-RPCの説明は以下に有ります。Thrift等のプロダクトと比べると、非常に高速なのに加えて、非同期呼び出しをサポートしているのが利点です。

• Introduction to MessagePack-RPC
• 並列メッセージングフレームワーク「MessagePack-RPC for C++」リリース
• MessagePack-RPCのプロトコル仕様（ドラフト）と実装例

MessagePack-RPCは従来C++/Ruby版のみが提供されていました。ただ、広めるに当たっては様々な言語でのサポートが必須です。

そこでゴールデンウィークを利用し、Java版/Python版のRPCライブラリを実装しました。Ruby版のコードを参考にしています。どちらも更なる検証・負荷実験が必要ですが、圧縮機能を除く一通りの機能は有ります。

各言語のバージョンは、その言語の一番良さそうなイベントライブラリを用いるというポリシーで開発しています。Java版はJBoss netty, Python版はTwistedを用いました。Ruby版はRev, C++版はmpioが用いられています。

開発したものは、githubにあります。

• msgpack-rpc github

実験的に、Java版をApache Cassandraに組み込み、get関数をRubyから叩いたりしてみました。ただ、MessagePack-RPCでは現在IDLからのコードジェネレーターが無いので、カスタムなデータ型をやりとりするのが非常に面倒くさいという問題が認識できました。

コードジェネレーターは、実は今、古橋さんが開発中です。Thrift互換のIDLを採用するため、Thriftを使用しているプロダクトは簡単にMessagePack-RPCに乗り換えられるようになっています。

Thriftは非常に良いライブラリなのですが、仕事で使ったときに色々と痛い目を見て、ベストなものでは無いと個人的には思っているので、MessagePack-RPCでそこら辺の問題を解決したいと思っています。

MessagePack-RPCはまだまだ成熟したプロダクトではないですが、徐々に完成度を上げていきたいと思っていますので、もし多言語間で通信するタスクが発生した場合には、使ってみてください:-) 将来的にはInfiniband/SDP(Socket Direct Protocol)などにも対応したい所です。

何か有れば、@kzk_moverまでお願いします。

修論提出done！ 2年前は真剣に学校ヤメようと思ってたのに、なんとか出したようです。後は修論発表が残っています。色々重なって、この１週間〜２週間は人生で一番忙しく、気持ちの浮き沈みが激しかった気がします。

2/18には京都でWPSE (International Workshop on Peta-Scale Computing Programming Environment, Languages and Tools) 2010というe-Science関係のワークショップが有って、少し話させて頂く予定です。

しかし、Alok Choudharyの前にI/Oの話をするのは、順番的にどうなの。

今年は飛行機に乗りまくった年でした。去年まで１年に１回程度だったのに。リストアップすると、石垣島(1week)、上海(1week)、シカゴ(2 months)、ハワイ(1week)、ニューヨーク(4 days), ボルドー(2weeks)。

特にシカゴの二ヶ月が大きかったです。米国で住んでみると、いろいろ体験できるものでした。英語での日常会話には困らなくなりました。ビジネスの交渉とか、多人数のディスカッションとなると少し厳しいので、来年度の課題です。

根本的にはボキャブラリが足りないのと、ネイティブのスピードに付いていけないのが問題です。2人だったら聞き返せばいいのですが、3人以上だと、気を抜くと置いていかれる。ニュースを聞き取れるぐらいになると良いのかなあ。あとは研究所の雰囲気を味わえたのが良かったです。

コーディングの方はというと、今年のコミット数は660ぐらい。去年が1100だった事を考えると、4割減とはかなりお寒い数字ですね…。まあその他の仕事が増えてきたと言うのも有りますけど、もうちょいなんとかならなかったのかと。集中できる時間が少なかった気がするので、来年はなんとか盛り返したいと思います。

研究の方は、1st Authorでの論文は出せなかった。来年前半に出します。CCGRID2009で発表しました。論文はかなり読んでますが、アウトプットが無いのが問題。今は修士論文を書いていて、来年卒業予定です。

会社の方は、順調に売上が伸びてます。色々なところで、割と競争力が出てきた感じ。来年度はもっと洗練させて、儲けて、ガンガン良い人を雇って行くと共に、海外で売るのが目標です。あとはサマーインターンを取ったのも、非常に大きな出来事でした。これは、楽しかった。

プレゼンはITProカンファレンス、天下一カウボーイ大会、楽天テクノロジーカンファレンス、Cookpad TechLife、Shibuya.pm等で行わせて頂きました。あとはKey-Value Store勉強会、Hadoop Conference Japan 2009の運営側をやりました。お手伝い頂いた方々に感謝。来年も技術的に面白そうな集まりは是非やりたいです。

あとは松葉さんからお古のレンズ(ZUIKO DIGITAL 14-54mm F2.8-3.5)を安く譲ってもらってから、結構楽しくなってきました。デフォルトレンズだと全体的に暗かったんですよね。FacebookとかPicasaにアップして色々コメントを貰えるのが楽しいですね:-)

では、来年もよろしくお願いいたします！