phpで発生したMemcachedのエラーをソースコードから追ってみた

背景

phpのWebアプリで、MemcachedのエクステンションをMemcacheから、Memcachedに移行する際、アプリのデバッグ中に発生したエラーについて、どこで発生しているのかを追った。

エラーログの内容

error_code -> 37 : ITEM TOO BIG host: array (  'host' => '/tmp/memcache.sock',  'port' => 0,  'persistent_str' => '***',) key:***

エクステンションをMemcachedに切り替えた際に発生した。Memcacheの時は特に出ていなかった。
Memcachedに切り替えたのが原因のため、まずはそちらのソースを追う事に。

調査内容

php-memcached

バージョン：2.2.0
ダウンロード先：https://pecl.php.net/package/memcached

php_memcached.c

#include "php_memcached_private.h"

php_memcached_private.h

#include "php_libmemcached_compat.h"

php_libmemcached_compat.h

#include <libmemcached/memcached.h>

libmemcachedライブラリを使用している事が判明。
どうやらphp-memcachedはphp用のlibmemcachedラッパーのようなので、
次にlibmemcached本体を調査。

libmemcached

バージョン：1.0.18
ダウンロード先：https://launchpad.net/libmemcached/+download

libmemcached/strerror.cc

#include <libmemcached/common.h>
～中略～
const char *memcached_strerror(const memcached_st *, memcached_return_t rc)
{
  switch (rc)
  {
  ～中略～
  case MEMCACHED_E2BIG:
    return "ITEM TOO BIG";
  ～中略～
}

Memcachedサーバからのリターンコードrcの値を定数と比較し、該当するメッセージを返している。
rcの値がMEMCACHED_E2BIGの場合に「ITEM TOO BIG」のメッセージを返している。
ここでメッセージ本体はlibmemcachedに記載されている事が判明。
次にMEMCACHED_E2BIGの定義箇所を探した。

libmemcached/common.h

#include <libmemcached-1.0/memcached.h> 

libmemcached-1.0/memcached.h

#include <libmemcached-1.0/types/return.h>

libmemcached-1.0/types/return.h

enum memcached_return_t {
  MEMCACHED_SUCCESS,
  MEMCACHED_FAILURE,
  MEMCACHED_HOST_LOOKUP_FAILURE, // getaddrinfo() and getnameinfo() only
  MEMCACHED_CONNECTION_FAILURE,
  MEMCACHED_CONNECTION_BIND_FAILURE,  // DEPRECATED, see MEMCACHED_HOST_LOOKUP_FAILURE
  MEMCACHED_WRITE_FAILURE,
  MEMCACHED_READ_FAILURE,
  MEMCACHED_UNKNOWN_READ_FAILURE,
  MEMCACHED_PROTOCOL_ERROR,
  MEMCACHED_CLIENT_ERROR,
  MEMCACHED_SERVER_ERROR, // Server returns "SERVER_ERROR"
  MEMCACHED_ERROR, // Server returns "ERROR"
  MEMCACHED_DATA_EXISTS,
  MEMCACHED_DATA_DOES_NOT_EXIST,
  MEMCACHED_NOTSTORED,
  MEMCACHED_STORED,
  MEMCACHED_NOTFOUND,
  MEMCACHED_MEMORY_ALLOCATION_FAILURE,
  MEMCACHED_PARTIAL_READ,
  MEMCACHED_SOME_ERRORS,
  MEMCACHED_NO_SERVERS,
  MEMCACHED_END,
  MEMCACHED_DELETED,
  MEMCACHED_VALUE,
  MEMCACHED_STAT,
  MEMCACHED_ITEM,
  MEMCACHED_ERRNO,
  MEMCACHED_FAIL_UNIX_SOCKET, // DEPRECATED
  MEMCACHED_NOT_SUPPORTED,
  MEMCACHED_NO_KEY_PROVIDED, /* Deprecated. Use MEMCACHED_BAD_KEY_PROVIDED! */
  MEMCACHED_FETCH_NOTFINISHED,
  MEMCACHED_TIMEOUT,
  MEMCACHED_BUFFERED,
  MEMCACHED_BAD_KEY_PROVIDED,
  MEMCACHED_INVALID_HOST_PROTOCOL,
  MEMCACHED_SERVER_MARKED_DEAD,
  MEMCACHED_UNKNOWN_STAT_KEY,
  MEMCACHED_E2BIG,
  MEMCACHED_INVALID_ARGUMENTS,
  MEMCACHED_KEY_TOO_BIG,
  MEMCACHED_AUTH_PROBLEM,
  MEMCACHED_AUTH_FAILURE,
  MEMCACHED_AUTH_CONTINUE,
  MEMCACHED_PARSE_ERROR,
  MEMCACHED_PARSE_USER_ERROR,
  MEMCACHED_DEPRECATED,
  MEMCACHED_IN_PROGRESS,
  MEMCACHED_SERVER_TEMPORARILY_DISABLED,
  MEMCACHED_SERVER_MEMORY_ALLOCATION_FAILURE,
  MEMCACHED_MAXIMUM_RETURN, /* Always add new error code before */
  MEMCACHED_CONNECTION_SOCKET_CREATE_FAILURE= MEMCACHED_ERROR
};

enumで列挙されていた。

さらにMEMCACHED_E2BIGを返している箇所を捜索。

libmemcached/response.cc

static memcached_return_t textual_read_one_response(memcached_instance_st* instance,
                                                    char *buffer, const size_t buffer_length,
                                                    memcached_result_st *result)
{
  ～中略～
  switch(buffer[0])
  {
  ～中略～
  case 'S':
    {
      // STAT
      if (buffer[1] == 'T' and buffer[2] == 'A' and buffer[3] == 'T') /* STORED STATS */
      {
        memcached_server_response_increment(instance);
        return MEMCACHED_STAT;
      }
      // SERVER_ERROR
      else if (buffer[1] == 'E' and buffer[2] == 'R' and buffer[3] == 'V' and buffer[4] == 'E' and buffer[5] == 'R'
               and buffer[6] == '_'
               and buffer[7] == 'E' and buffer[8] == 'R' and buffer[9] == 'R' and buffer[10] == 'O' and buffer[11] == 'R' )
      {
        if (total_read == memcached_literal_param_size("SERVER_ERROR"))
        {
          return MEMCACHED_SERVER_ERROR;
        }

        if (total_read >= memcached_literal_param_size("SERVER_ERROR object too large for cache") and
            (memcmp(buffer, memcached_literal_param("SERVER_ERROR object too large for cache")) == 0))
        {
          return MEMCACHED_E2BIG;
        }

        if (total_read >= memcached_literal_param_size("SERVER_ERROR out of memory storing object") and
            (memcmp(buffer, memcached_literal_param("SERVER_ERROR out of memory storing object")) == 0))
        {
          return MEMCACHED_SERVER_MEMORY_ALLOCATION_FAILURE;
        }

        // Move past the basic error message and whitespace
        char *startptr= buffer + memcached_literal_param_size("SERVER_ERROR");
        if (startptr[0] == ' ')
        {
          startptr++;
        }

        char *endptr= startptr;
        while (*endptr != '\r' && *endptr != '\n') endptr++;

        return memcached_set_error(*instance, MEMCACHED_SERVER_ERROR, MEMCACHED_AT, startptr, size_t(endptr - startptr));
      }
      // STORED
      else if (buffer[1] == 'T' and buffer[2] == 'O' and buffer[3] == 'R') //  and buffer[4] == 'E' and buffer[5] == 'D')
      {
        return MEMCACHED_STORED;
      }
    }
    break;
  ～中略～
}

Memcachedサーバからのレスポンスがbufferに格納されていており、それが「SERVER_ERROR」で始まっているかを判定している。
MEMCACHED_E2BIGが返るのは、メッセージが「SERVER_ERROR object too large for cache」の時。
サーバ側のコードも見る必要があるのでさらに調査を続けた。

Memcached

バージョン：1.4.24
ダウンロード先：http://memcached.org/downloads

memcached.c

static void process_update_command(conn *c, token_t *tokens, const size_t ntokens, int comm, bool handle_cas) {
    char *key;
    size_t nkey;
    unsigned int flags;
    int32_t exptime_int = 0;
    time_t exptime;
    int vlen;
    uint64_t req_cas_id=0;
    item *it;

    assert(c != NULL);

    set_noreply_maybe(c, tokens, ntokens);

    if (tokens[KEY_TOKEN].length > KEY_MAX_LENGTH) {
        out_string(c, "CLIENT_ERROR bad command line format");
        return;
    }

    key = tokens[KEY_TOKEN].value;
    nkey = tokens[KEY_TOKEN].length;

    if (! (safe_strtoul(tokens[2].value, (uint32_t *)&flags)
           && safe_strtol(tokens[3].value, &exptime_int)
           && safe_strtol(tokens[4].value, (int32_t *)&vlen))) {
        out_string(c, "CLIENT_ERROR bad command line format");
        return;
    }

    /* Ubuntu 8.04 breaks when I pass exptime to safe_strtol */
    exptime = exptime_int;

    /* Negative exptimes can underflow and end up immortal. realtime() will
       immediately expire values that are greater than REALTIME_MAXDELTA, but less
       than process_started, so lets aim for that. */
    if (exptime < 0)
        exptime = REALTIME_MAXDELTA + 1;

    // does cas value exist?
    if (handle_cas) {
        if (!safe_strtoull(tokens[5].value, &req_cas_id)) {
            out_string(c, "CLIENT_ERROR bad command line format");
            return;
        }
    }

    vlen += 2;
    if (vlen < 0 || vlen - 2 < 0) {
        out_string(c, "CLIENT_ERROR bad command line format");
        return;
    }

    if (settings.detail_enabled) {
        stats_prefix_record_set(key, nkey);
    }

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

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

        /* Avoid stale data persisting in cache because we failed alloc.
         * Unacceptable for SET. Anywhere else too? */
        if (comm == NREAD_SET) {
            it = item_get(key, nkey);
            if (it) {
                item_unlink(it);
                item_remove(it);
            }
        }

        return;
    }
  ～中略～
}

item_size_ok()の結果が0の場合に「SERVER_ERROR object too large for cache」メッセージを返している。
引数nkey, flags, vlenはprocess_update_command()の引数tokensから求めている。
process_update_command()はprocess_command()から呼ばれている。
process_command()はMemcachedに送られたコマンドを解析するための処理らしい。
以下該当箇所のみ抜粋。

static void process_command(conn *c, char *command) {

    token_t tokens[MAX_TOKENS];
    size_t ntokens;
    int comm;
  ～中略～

    c->msgcurr = 0;
    c->msgused = 0;
    c->iovused = 0;
    if (add_msghdr(c) != 0) {
        out_of_memory(c, "SERVER_ERROR out of memory preparing response");
        return;
    }

    ntokens = tokenize_command(command, tokens, MAX_TOKENS);
    if (ntokens >= 3 &&
        ((strcmp(tokens[COMMAND_TOKEN].value, "get") == 0) ||
         (strcmp(tokens[COMMAND_TOKEN].value, "bget") == 0))) {

        process_get_command(c, tokens, ntokens, false);

    } else if ((ntokens == 6 || ntokens == 7) &&
               ((strcmp(tokens[COMMAND_TOKEN].value, "add") == 0 && (comm = NREAD_ADD)) ||
                (strcmp(tokens[COMMAND_TOKEN].value, "set") == 0 && (comm = NREAD_SET)) ||
                (strcmp(tokens[COMMAND_TOKEN].value, "replace") == 0 && (comm = NREAD_REPLACE)) ||
                (strcmp(tokens[COMMAND_TOKEN].value, "prepend") == 0 && (comm = NREAD_PREPEND)) ||
                (strcmp(tokens[COMMAND_TOKEN].value, "append") == 0 && (comm = NREAD_APPEND)) )) {

        process_update_command(c, tokens, ntokens, comm, false);
  ～中略～
}

ここで、item_size_ok()の結果が0になるケースが気になったのでさらに調査を進めた。

#include "memcached.h"

memcached.h

#include "slabs.h"
#include "items.h"

items.c

bool item_size_ok(const size_t nkey, const int flags, const int nbytes) {
    char prefix[40];
    uint8_t nsuffix;

    size_t ntotal = item_make_header(nkey + 1, flags, nbytes,
                                     prefix, &nsuffix);
    if (settings.use_cas) {
        ntotal += sizeof(uint64_t);
    }

    return slabs_clsid(ntotal) != 0;
}

slabs_clsid()が0以外であれば0が返る。

memcached.h

#include "slabs.h"
  ～中略～
#define POWER_SMALLEST 1
#define POWER_LARGEST  256 /* actual cap is 255 */
#define CHUNK_ALIGN_BYTES 8
#define MAX_NUMBER_OF_SLAB_CLASSES (63 + 1)

slabs.c

static int power_largest;
  ～中略～
unsigned int slabs_clsid(const size_t size) {
    int res = POWER_SMALLEST;

    if (size == 0)
        return 0;
    while (size > slabclass[res].size)
        if (res++ == power_largest)     /* won't fit in the biggest slab */
            return 0;
    return res;
}

power_largestの値を超えた際にエラーとなる。
power_largestはslabs_init()で初期化されている。
slabs_init()はmemcached.cのmain()から呼び出されており、
引数limitに設定maxbytes、factorに設定factorの値を渡している。

void slabs_init(const size_t limit, const double factor, const bool prealloc) {
    int i = POWER_SMALLEST - 1;
    unsigned int size = sizeof(item) + settings.chunk_size;

    mem_limit = limit;

    if (prealloc) {
        /* Allocate everything in a big chunk with malloc */
        mem_base = malloc(mem_limit);
        if (mem_base != NULL) {
            mem_current = mem_base;
            mem_avail = mem_limit;
        } else {
            fprintf(stderr, "Warning: Failed to allocate requested memory in"
                    " one large chunk.\nWill allocate in smaller chunks\n");
        }
    }

    memset(slabclass, 0, sizeof(slabclass));

    while (++i < MAX_NUMBER_OF_SLAB_CLASSES-1 && size <= settings.item_size_max / factor) {
        /* Make sure items are always n-byte aligned */
        if (size % CHUNK_ALIGN_BYTES)
            size += CHUNK_ALIGN_BYTES - (size % CHUNK_ALIGN_BYTES);

        slabclass[i].size = size;
        slabclass[i].perslab = settings.item_size_max / slabclass[i].size;
        size *= factor;
        if (settings.verbose > 1) {
            fprintf(stderr, "slab class %3d: chunk size %9u perslab %7u\n",
                    i, slabclass[i].size, slabclass[i].perslab);
        }
    }

    power_largest = i;
    slabclass[power_largest].size = settings.item_size_max;
    slabclass[power_largest].perslab = 1;
    if (settings.verbose > 1) {
        fprintf(stderr, "slab class %3d: chunk size %9u perslab %7u\n",
                i, slabclass[i].size, slabclass[i].perslab);
    }

    /* for the test suite:  faking of how much we've already malloc'd */
    {
        char *t_initial_malloc = getenv("T_MEMD_INITIAL_MALLOC");
        if (t_initial_malloc) {
            mem_malloced = (size_t)atol(t_initial_malloc);
        }

    }

    if (prealloc) {
        slabs_preallocate(power_largest);
    }
}

MAX_NUMBER_OF_SLAB_CLASSES-1(63)になるまでスラブ毎のサイズを計算している。
power_largestの値はMAX_NUMBER_OF_SLAB_CLASSES-1と等しくなり、
この時のサイズは設定item_size_maxの値になる。
設定初期化はmemcached.c内のsettings_init()関数で行われており、item_size_maxは1024 * 1024 = 1MBで定義されている。

memcached.c

static void settings_init(void) {
    settings.use_cas = true;
    settings.access = 0700;
    settings.port = 11211;
    settings.udpport = 11211;
    /* By default this string should be NULL for getaddrinfo() */
    settings.inter = NULL;
    settings.maxbytes = 64 * 1024 * 1024; /* default is 64MB */
    settings.maxconns = 1024;         /* to limit connections-related memory to about 5MB */
    settings.verbose = 0;
    settings.oldest_live = 0;
    settings.oldest_cas = 0;          /* supplements accuracy of oldest_live */
    settings.evict_to_free = 1;       /* push old items out of cache when memory runs out */
    settings.socketpath = NULL;       /* by default, not using a unix socket */
    settings.factor = 1.25;
    settings.chunk_size = 48;         /* space for a modest key and value */
    settings.num_threads = 4;         /* N workers */
    settings.num_threads_per_udp = 0;
    settings.prefix_delimiter = ':';
    settings.detail_enabled = 0;
    settings.reqs_per_event = 20;
    settings.backlog = 1024;
    settings.binding_protocol = negotiating_prot;
    settings.item_size_max = 1024 * 1024; /* The famous 1MB upper limit. */
    settings.maxconns_fast = false;
    settings.lru_crawler = false;
    settings.lru_crawler_sleep = 100;
    settings.lru_crawler_tocrawl = 0;
    settings.lru_maintainer_thread = false;
    settings.hot_lru_pct = 32;
    settings.warm_lru_pct = 32;
    settings.expirezero_does_not_evict = false;
    settings.hashpower_init = 0;
    settings.slab_reassign = false;
    settings.slab_automove = 0;
    settings.shutdown_command = false;
    settings.tail_repair_time = TAIL_REPAIR_TIME_DEFAULT;
    settings.flush_enabled = true;
    settings.crawls_persleep = 1000;
}

ここでソースコードの調査は一旦中断し、起動中のMemcachedの設定を確認する。

$ echo 'stats settings' | nc localhost 11211 | grep item_size_max
STAT item_size_max 1048576

確かに1MBである。

結論

item_size_maxの設定より大きなサイズのデータをキャッシュしようとしてエラーログが出た。
Memcachedには1MBを超えるデータは載せないよう心がけましょう。

補足

item_size_maxの値は「-I」オプションで変更可能だが、1MBを超える値を設定しようとするとWARNINGが出る。

$ memcached -u memcached -p 11211 -I 10m
WARNING: Setting item max size above 1MB is not recommended!
 Raising this limit increases the minimum memory requirements
 and will decrease your memory efficiency.

WARNINGはmemcached.cのmain()内で出ている。

memcached.c

int main (int argc, char **argv) {
  ～中略～
        case 'I':
            buf = strdup(optarg);
            unit = buf[strlen(buf)-1];
            if (unit == 'k' || unit == 'm' ||
                unit == 'K' || unit == 'M') {
                buf[strlen(buf)-1] = '\0';
                size_max = atoi(buf);
                if (unit == 'k' || unit == 'K')
                    size_max *= 1024;
                if (unit == 'm' || unit == 'M')
                    size_max *= 1024 * 1024;
                settings.item_size_max = size_max;
            } else {
                settings.item_size_max = atoi(buf);
            }
            if (settings.item_size_max < 1024) {
                fprintf(stderr, "Item max size cannot be less than 1024 bytes.\n");
                return 1;
            }
            if (settings.item_size_max > 1024 * 1024 * 128) {
                fprintf(stderr, "Cannot set item size limit higher than 128 mb.\n");
                return 1;
            }
            if (settings.item_size_max > 1024 * 1024) {
                fprintf(stderr, "WARNING: Setting item max size above 1MB is not"
                    " recommended!\n"
                    " Raising this limit increases the minimum memory requirements\n"
                    " and will decrease your memory efficiency.\n"
                );
            }
            free(buf);
            break;
  ～中略～
}