REdis CPU百分百问题分析

 

REdis版本：4.0.9

运行环境：Linux 3.10.107 x86_64 gcc_version:4.8.5

结论：是一个BUG，在4.0.11版本中被作者antirez所修复

 

现象：

1) top显示

 

2) 执行REdis info命令直接卡住不动

3) 集群通讯端口大量的“CLOSE_WAIT”

4) 日志文件大量的“Bad message length or signature received from Cluster bus”

5) 物理内存和虚拟内存均占用不高（配置最大内存为5G，实际占用物理内存才4M多）

6) 通过其它正常节点查看，该故障节点处于“fail”状态

 

推测：发生了死循环。

 

GDB分析：

(gdb) bt

#0  je_malloc (size=size@entry=47) at src/jemalloc.c:1425

#1  0x00000000004329ee in zmalloc (size=size@entry=47) at zmalloc.c:98

#2  0x000000000043cea9 in createEmbeddedStringObject (ptr=0x7f5da721b101 "dog:cgi:proj_trans_query_hb", len=27) at object.c:85

#3  0x000000000043cf65 in createStringObject (ptr=ptr@entry=0x7f5da721b101 "dog:cgi:proj_trans_query_hb", len=<optimized out>) at object.c:119

#4  0x000000000044141b in dbRandomKey (db=0x7f5da72d5000) at db.c:236

#5  0x00000000004414c2 in randomkeyCommand (c=0x7f5da6dd9e00) at db.c:498

#6  0x000000000042c03e in call (c=c@entry=0x7f5da6dd9e00, flags=flags@entry=15) at server.c:2229

#7  0x000000000042c6e7 in processCommand (c=0x7f5da6dd9e00) at server.c:2510

#8  0x000000000043b745 in processInputBuffer (c=0x7f5da6dd9e00) at networking.c:1354

#9  0x00000000004267f0 in aeProcessEvents (eventLoop=eventLoop@entry=0x7f5da723a050, flags=flags@entry=11) at ae.c:440

#10 0x0000000000426adb in aeMain (eventLoop=0x7f5da723a050) at ae.c:498

#11 0x00000000004238ef in main (argc=<optimized out>, argv=0x7ffc0451ab58) at server.c:3894

(gdb) f 5

#5  0x00000000004414c2 in randomkeyCommand (c=0x7f5da6dd9e00) at db.c:498

498     db.c: No such file or directory.

(gdb) p *c

$7 = {id = 144, fd = 78, db = 0x7f5da72d5000, name = 0x0, querybuf = 0x7f5da70ae285 "", pending_querybuf = 0x7f5da7216743 "", querybuf_peak = 0, argc = 1, argv = 0x7f5da72167f0, 

  cmd = 0x741820 <redisCommandTable+7520>, lastcmd = 0x741820 <redisCommandTable+7520>, reqtype = 2, multibulklen = 0, bulklen = -1, reply = 0x7f5da6d20ea0, reply_bytes = 0, 

  sentlen = 0, ctime = 1542039740, lastinteraction = 1542039740, obuf_soft_limit_reached_time = 0, flags = 0, authenticated = 0, replstate = 0, repl_put_online_on_ack = 0, 

  repldbfd = -1496183376, repldboff = 0, repldbsize = 0, replpreamble = 0x5bdb29d9 <Address 0x5bdb29d9 out of bounds>, read_reploff = 0, reploff = 0, repl_ack_off = 0, 

  repl_ack_time = 0, psync_initial_offset = 1090943882, 

  replid = "00000000]17700000000000000000000216000000000000003773773773770000000000P-247]1770000", 

  slave_listening_port = 0, slave_ip = "0000000000000000243k!247]177", '00' <repeats 14 times>, "]1770000@g!247]17700000000000000", 

  slave_capa = 0, mstate = {commands = 0x0, count = 0, minreplicas = -1, minreplicas_timeout = 140040207470240}, btype = 0, bpop = {timeout = 0, keys = 0x7f5da72b2aa0, target = 0x0, 

    numreplicas = 0, reploffset = 0, module_blocked_handle = 0x0}, woff = 0, watched_keys = 0x7f5da6d20e70, pubsub_channels = 0x7f5da72b2b00, pubsub_patterns = 0x7f5da6d20ed0, 

  peerid = 0x0, bufpos = 0, 

  buf = '00' <repeats 20 times>, "23.Kp0000000024016322246]177000000++247]177000032016322246]177", '00' <repeats 14 times>, "$-1 ", '00' <repeats 39 times>, "240*+247]177", '00' <repeats 34 times>, "242;223<0000000000000000]17700000000000000000000240*+247]177", '00' <repeats 14 times>, "$-1 ", '00' <repeats 16 times>...}

(gdb) p *c->cmd

$8 = {name = 0x4f3026 "randomkey", proc = 0x4414b0 <randomkeyCommand>, arity = 1, sflags = 0x4f2e87 "rR", flags = 130, getkeys_proc = 0x0, firstkey = 0, lastkey = 0, keystep = 0, 

  microseconds = 139, calls = 67}

(gdb) c

Continuing.

^C

Program received signal SIGINT, Interrupt.

0x00007f5da782339b in random () from /lib64/libc.so.6

(gdb) bt

#0  0x00007f5da782339b in random () from /lib64/libc.so.6

#1  0x0000000000428bf5 in dictGetRandomKey (d=0x7f5da7218360) at dict.c:630

#2  0x00000000004413e0 in dbRandomKey (db=0x7f5da72d5000) at db.c:232

#3  0x00000000004414c2 in randomkeyCommand (c=0x7f5da6dd9e00) at db.c:498

#4  0x000000000042c03e in call (c=c@entry=0x7f5da6dd9e00, flags=flags@entry=15) at server.c:2229

#5  0x000000000042c6e7 in processCommand (c=0x7f5da6dd9e00) at server.c:2510

#6  0x000000000043b745 in processInputBuffer (c=0x7f5da6dd9e00) at networking.c:1354

#7  0x00000000004267f0 in aeProcessEvents (eventLoop=eventLoop@entry=0x7f5da723a050, flags=flags@entry=11) at ae.c:440

#8  0x0000000000426adb in aeMain (eventLoop=0x7f5da723a050) at ae.c:498

#9  0x00000000004238ef in main (argc=<optimized out>, argv=0x7ffc0451ab58) at server.c:3894

(gdb) f 3

#3  0x00000000004414c2 in randomkeyCommand (c=0x7f5da6dd9e00) at db.c:498

498     in db.c

(gdb) p *c

$9 = {id = 144, fd = 78, db = 0x7f5da72d5000, name = 0x0, querybuf = 0x7f5da70ae285 "", pending_querybuf = 0x7f5da7216743 "", querybuf_peak = 0, argc = 1, argv = 0x7f5da72167f0, 

  cmd = 0x741820 <redisCommandTable+7520>, lastcmd = 0x741820 <redisCommandTable+7520>, reqtype = 2, multibulklen = 0, bulklen = -1, reply = 0x7f5da6d20ea0, reply_bytes = 0, 

  sentlen = 0, ctime = 1542039740, lastinteraction = 1542039740, obuf_soft_limit_reached_time = 0, flags = 0, authenticated = 0, replstate = 0, repl_put_online_on_ack = 0, 

  repldbfd = -1496183376, repldboff = 0, repldbsize = 0, replpreamble = 0x5bdb29d9 <Address 0x5bdb29d9 out of bounds>, read_reploff = 0, reploff = 0, repl_ack_off = 0, 

  repl_ack_time = 0, psync_initial_offset = 1090943882, 

  replid = "00000000]17700000000000000000000216000000000000003773773773770000000000P-247]1770000", 

  slave_listening_port = 0, slave_ip = "0000000000000000243k!247]177", '00' <repeats 14 times>, "]1770000@g!247]17700000000000000", 

  slave_capa = 0, mstate = {commands = 0x0, count = 0, minreplicas = -1, minreplicas_timeout = 140040207470240}, btype = 0, bpop = {timeout = 0, keys = 0x7f5da72b2aa0, target = 0x0, 

    numreplicas = 0, reploffset = 0, module_blocked_handle = 0x0}, woff = 0, watched_keys = 0x7f5da6d20e70, pubsub_channels = 0x7f5da72b2b00, pubsub_patterns = 0x7f5da6d20ed0, 

  peerid = 0x0, bufpos = 0, 

  buf = '00' <repeats 20 times>, "23.Kp0000000024016322246]177000000++247]177000032016322246]177", '00' <repeats 14 times>, "$-1 ", '00' <repeats 39 times>, "240*+247]177", '00' <repeats 34 times>, "242;223<0000000000000000]17700000000000000000000240*+247]177", '00' <repeats 14 times>, "$-1 ", '00' <repeats 16 times>...}

(gdb) p *c->cmd

$10 = {name = 0x4f3026 "randomkey", proc = 0x4414b0 <randomkeyCommand>, arity = 1, sflags = 0x4f2e87 "rR", flags = 130, getkeys_proc = 0x0, firstkey = 0, lastkey = 0, keystep = 0, 

  microseconds = 139, calls = 67}

 

从两次不同时间点的数据看，c的地址未发生变化，是同一对象。对照相应版本的源代码，找有循环的地方缩小范围，确定死循环发生的具体函数。

/* Return a random key, in form of a Redis object.

 * If there are no keys, NULL is returned.

 *

 * The function makes sure to return keys not already expired. */

robj *dbRandomKey(redisDb *db) { // db.c:225

    dictEntry *de;

 

    while(1) {

        sds key;

        robj *keyobj;

 

        de = dictGetRandomKey(db->dict); // db.c:232

        if (de == NULL) return NULL;

 

        key = dictGetKey(de);

        keyobj = createStringObject(key,sdslen(key));

        if (dictFind(db->expires,key)) {

            if (expireIfNeeded(db,keyobj)) {

                decrRefCount(keyobj);

                continue; /* search for another key. This expired. */

            }

        }

        return keyobj;

    }

}

 

void randomkeyCommand(client *c) { // db.c:495

    robj *key;

 

    if ((key = dbRandomKey(c->db)) == NULL) { // db.c:498

        addReply(c,shared.nullbulk);

        return;

    }

 

    // 在这里打一断点，如果没执行到这，

    // 即可确定函数dbRandomKey发生死循环

    addReplyBulk(c,key); // db.c:503

    decrRefCount(key);

}

 

/* Return a random entry from the hash table. Useful to

 * implement randomized algorithms */

dictEntry *dictGetRandomKey(dict *d) // dict.c:610

{

    dictEntry *he, *orighe;

    unsigned long h;

    int listlen, listele;

 

    if (dictSize(d) == 0) return NULL;

    if (dictIsRehashing(d)) _dictRehashStep(d);

    if (dictIsRehashing(d)) {

        do {

            /* We are sure there are no elements in indexes from 0

             * to rehashidx-1 */

            h = d->rehashidx + (random() % (d->ht[0].size +

                                            d->ht[1].size -

                                            d->rehashidx));

            he = (h >= d->ht[0].size) ? d->ht[1].table[h - d->ht[0].size] :

                                      d->ht[0].table[h];

        } while(he == NULL);

    } else {

        do {

            h = random() & d->ht[0].sizemask; // dict.c:630

            he = d->ht[0].table[h];

        } while(he == NULL);

    }

 

    /* Now we found a non empty bucket, but it is a linked

     * list and we need to get a random element from the list.

     * The only sane way to do so is counting the elements and

     * select a random index. */

    listlen = 0;

    orighe = he;

    while(he) {

        he = he->next;

        listlen++;

    }

    listele = random() % listlen;

    he = orighe;

    while(listele--) he = he->next;

    return he;

}

 

经过GDB分析，死循环发生在函数dbRandomKey中，其中的“while(1)”退不出来。亦即走不到退出循环语句“if (de == NULL) return NULL;”。

 

估计是个BUG，查看新版本（5.0.4）的实现（dictSize在4.0.9和5.0.4两个版本源文件中的位置不变）：

#define dictSize(d) ((d)->ht[0].used+(d)->ht[1].used) // dict.h:147

 

/* Return a random key, in form of a Redis object.

 * If there are no keys, NULL is returned.

 *

 * The function makes sure to return keys not already expired. */

robj *dbRandomKey(redisDb *db) { // db.c:235

    dictEntry *de;

    int maxtries = 100; // 最多重试次数，可消除死循环，但是否起作用，还有两个前置条件

    int allvolatile = dictSize(db->dict) == dictSize(db->expires);

 

    while(1) {

        sds key;

        robj *keyobj;

 

        de = dictGetRandomKey(db->dict);

        if (de == NULL) return NULL;

 

        key = dictGetKey(de);

        keyobj = createStringObject(key,sdslen(key));

        if (dictFind(db->expires,key)) {

            if (allvolatile && server.masterhost && --maxtries == 0) {

                /* If the DB is composed only of keys with an expire set,

                 * it could happen that all the keys are already logically

                 * expired in the slave, so the function cannot stop because

                 * expireIfNeeded() is false, nor it can stop because

                 * dictGetRandomKey() returns NULL (there are keys to return).

                 * To prevent the infinite loop we do some tries, but if there

                 * are the conditions for an infinite loop, eventually we

                 * return a key name that may be already expired. */

                return keyobj;

            }

            if (expireIfNeeded(db,keyobj)) {

                decrRefCount(keyobj);

                continue; /* search for another key. This expired. */

            }

        }

        return keyobj;

    }

}

 

确定4.0.9版本的“if (allvolatile && server.masterhost && --maxtries == 0) {”是否成立：

(gdb) p db->dict->ht[0].used

$11 = 1

(gdb) p db->dict->ht[1].used 

$12 = 0

(gdb) p server.masterhost

$13 = 0x7f5da7221f41 "10.11.34.35"

 

显然是可以进入if语句退出循环的，因此可以确定这是一个BUG，并且5.0.4版本已经修复了该问题，往前查4.0.11版本的实现已和5.0.4版本相同，也许更早的版本就已经修复了该问题。

通过查看RELEASENOTES，确定这个BUG是在4.0.11中修复的：

antirez in commit ab145a9f:

 Fix infinite loop in dbRandomKey().

 1 file changed, 13 insertions(+)