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 = "\000\000\000\000]\177\000\000\000\000\000\000\000\000\000\000\216\000\000\000\000\000\000\000\377\377\377\377\000\000\000\000\000P-\247]\177\000\000", slave_listening_port = 0, slave_ip = "\000\000\000\000\000\000\000\000\243k!\247]\177", '\000' <repeats 14 times>, "]\177\000\000@g!\247]\177\000\000\000\000\000\000\000", 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 = '\000' <repeats 20 times>, "\023.Kp\000\000\000\000\240\016\322\246]\177\000\000\000++\247]\177\000\000\320\016\322\246]\177", '\000' <repeats 14 times>, "$-1\r\n", '\000' <repeats 39 times>, "\240*+\247]\177", '\000' <repeats 34 times>, "\242;\223<\000\000\000\000\000\000\000\000]\177\000\000\000\000\000\000\000\000\000\000\240*+\247]\177", '\000' <repeats 14 times>, "$-1\r", '\000' <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 = "\000\000\000\000]\177\000\000\000\000\000\000\000\000\000\000\216\000\000\000\000\000\000\000\377\377\377\377\000\000\000\000\000P-\247]\177\000\000", slave_listening_port = 0, slave_ip = "\000\000\000\000\000\000\000\000\243k!\247]\177", '\000' <repeats 14 times>, "]\177\000\000@g!\247]\177\000\000\000\000\000\000\000", 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 = '\000' <repeats 20 times>, "\023.Kp\000\000\000\000\240\016\322\246]\177\000\000\000++\247]\177\000\000\320\016\322\246]\177", '\000' <repeats 14 times>, "$-1\r\n", '\000' <repeats 39 times>, "\240*+\247]\177", '\000' <repeats 34 times>, "\242;\223<\000\000\000\000\000\000\000\000]\177\000\000\000\000\000\000\000\000\000\000\240*+\247]\177", '\000' <repeats 14 times>, "$-1\r", '\000' <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(+) |
