memcached で SERVER_ERROR out of memory storing object というエラー

ちょっと前にエントリにも書いた業務アプリですが、セッション管理に repcached を使っています。repcached とは memcached にデータのレプリケーション機能を追加実装したもので KLab 株式会社が開発したソフトウェアです。レプリケーションの機能により可用性は飛躍的に向上しているかわりに、まぁぶっちゃけ速度はかなり犠牲になっています。※ベンチマークをとったわけではないけど負荷テストで体感できるくらい違う。

さて、今回のアプリケーションサーバの構成としては、Oracle RAC + memcached でオラクルでも快適なセッション管理を！　で書いたような以下の構成になっています。

memcached のメモリには 1GB を割り当てていたのですが、ちょっとメモリが少なかったようです。運用し始めて数日後にセッションが保持されない不具合にみまわれました。随所に warn を仕込んでトレースしてみると、どうやら memcached が以下のエラーを吐いている模様。

思いがけず memcached のソースを読むことになりました。

結論からするとメモリ不足のようです。しかもこの事象は後述しますが repcached 特有のものであることも確認しました。memcached-1.2.6-repcached-2.2 のソースコードで言うと、memcached.c 1532 行目の部分でのエラーです。

static void process_update_command(conn *c, token_t *tokens, const size_t ntokens, int comm, bool handle_cas) {
    char *key;
    size_t nkey;

〜中略〜

    it = item_alloc(key, nkey, flags, realtime(exptime), vlen+2);

    if (it == 0) {
        if (! item_size_ok(nkey, flags, vlen + 2))
            out_string(c, "SERVER_ERROR object too large for cache");
        else
            out_string(c, "SERVER_ERROR out of memory storing object");
        /* swallow the data line */
        c->write_and_go = conn_swallow;
        c->sbytes = vlen + 2;

〜中略〜

同ロジックのメモリ不足のもう一つのエラー　SERVER_ERROR object too large for cache　に関しては以前もちょっと議論になったことがあったようで、この辺が参考になりました。

• のみまくし日記 - memcachedで新しくキャッシュを保存できないの刑
• のみまくし日記 - 続・memcachedで新しくキャッシュを保存できないの刑
• memcached で新しくキャッシュを保存出来ない？！ - にぽたん研究所
• きのうの memcached ネタ - にぽたん研究所
• memcached - Bulknews::Subtech - subtech

まぁ結果をいうと、上記の不具合はすでに memcached 側で改善されていて全く別の不具合だったわけなんですけど、テストスクリプトは参考にさせて頂きました。

頭が悪いので完全に追い切れなかったんですけど、repcached の場合、ある特定の条件で LRU による item の解放ができないみたいです。item.c の 124 行目〜あたりのヤツ。ロジックとしては最も古いデータから順に探索し、初めに出現した参照フラグなしの item を解放、最大５０個さかのぼっても解放できない場合はメモリ不足エラーとするって部分です。

item *do_item_alloc(char *key, const size_t nkey, const int flags, const rel_time_t exptime, const int nbytes) {
    uint8_t nsuffix;
    item *it;
    char suffix[40];
    size_t ntotal = item_make_header(nkey + 1, flags, nbytes, suffix, &nsuffix);

    unsigned int id = slabs_clsid(ntotal);
    if (id == 0)
        return 0;

    it = slabs_alloc(ntotal, id);
    if (it == 0) {
        int tries = 50;
        item *search;

        /* If requested to not push old items out of cache when memory runs out,
         * we're out of luck at this point...
         */

        if (settings.evict_to_free == 0) {
            itemstats[id].outofmemory++;
            return NULL;
        }

        /*
         * try to get one off the right LRU
         * don't necessariuly unlink the tail because it may be locked: refcount>0
         * search up from tail an item with refcount==0 and unlink it; give up after 50
         * tries
         */

        if (tails[id] == 0) {
            itemstats[id].outofmemory++;
            return NULL;
        }

        for (search = tails[id]; tries > 0 && search != NULL; tries--, search=search->prev) {
            if (search->refcount == 0) {
                if (search->exptime == 0 || search->exptime > current_time) {
                    itemstats[id].evicted++;
                    STATS_LOCK();
                    stats.evictions++;
                    STATS_UNLOCK();
#ifdef USE_REPLICATION
                    replication_call_del(ITEM_key(search), search->nkey);
#endif /* USE_REPLICATION */
                }
                do_item_unlink(search);
                break;
            }
        }
        it = slabs_alloc(ntotal, id);
        if (it == 0) {
            itemstats[id].outofmemory++;
            return NULL;
        }
    }

    assert(it->slabs_clsid == 0);

    it->slabs_clsid = id;

    assert(it != heads[it->slabs_clsid]);

    it->next = it->prev = it->h_next = 0;
    it->refcount = 1;     /* the caller will have a reference */
    DEBUG_REFCNT(it, '*');
    it->it_flags = 0;
    it->nkey = nkey;
    it->nbytes = nbytes;
    strcpy(ITEM_key(it), key);
    it->exptime = exptime;
    memcpy(ITEM_suffix(it), suffix, (size_t)nsuffix);
    it->nsuffix = nsuffix;
    return it;
}

なんだかエントリが長くなってきて、書くのが疲れてきましたが頑張ります。再現コードはこちら。格納するデータサイズを 1.3 倍していくことで memcached に新たな Slab を確保するように強いるコードです。メモリ不足で alloc できなくなったところで SEVER_ERROR が発生するはず。

192.168.0.1 / 192.168.0.2 の２台に repcached をインストールしている構成でお試しを。

use strict;
use Cache::Memcached;

my $size   = $ARGV[0] || 200000;
my $count  = $ARGV[1] || 10;
my $expire = $ARGV[2] || 2;

my $cache = Cache::Memcached->new({
    #servers => [ "192.168.0.1:10000" ],
    #servers => [ "192.168.0.2:10000" ],
    servers => [ "192.168.0.1:10000" , "192.168.0.2:10000" ],
    debug   => 0,
});

# XXX get immediately after storing
my $time = time;
print "store test\n";
for my $key ( 0 .. $count ) {
    $key = "$time$key";
    $cache->set( $key => "." x $size, $expire );
    my $stored = $cache->get($key);
    $size = $size * 1.3;
}

検証その１）　master + slave 構成　※このケースで不具合が発生する

memcached をデバッグモードで実行させておき、テストスクリプトを実行した際に出力されるデバッグメッセージを整形するとこんな感じになります。
SERVER_ERROR out of memory storing object　が出力されています。

検証その２）　master のみ起動の構成　※＝単体の memcached

この結果が本来の memcached の動作。メモリ不足でこれ以上 Slab が作成できないというエラーが出力されます。

検証その３）　master + slave 構成　※masterのみに接続するパターン

結果は検証２と同じで、違いは master でデータを STORED した際に REP コマンドで slave へデータが送られる点のみ。

検証その４）　master + slave 構成　※slaveのみに接続するパターン

こちらは若干シーケンスは変わるものの、結果的には検証２と同じ結果。LRU によるメモリ解放は master で管理されているっぽく、master で delete コマンドを発行させ、REP DELETE で slave 側のデータも削除しています。空きができたらやっと STORED 状態になると。※若干図が間違えてるけど・・・まぁいいや。

で、結局、なんで検証１の場合のみで初めの SERVER_ERROR が発生するのか、プログラムを追い切れませんでしたが、キャッシュの expire を短くし、割り当てるメモリを 1.5GB 程にして、当該エラーが発生しないようにアプリケーション側での調整で凌いでいます。本当は patch を書くところまでプログラムを追い切れれば良かったのですが、力尽きてしまいました・・・(^^ゞ

というわけで、結果的には今のところ快調に動いています。ｗ