Redis 4.0.2 crashed by signal: 11 when dataset size reaches 200+ GB

[astappiev]

The crash occurs every time when the size of instance reach 200+ GB (usually between 210-220GB), it doesn't depend on the amount of data (dbsize).

Also, I tried to split the data into two parts and both parts were successfully processed, so it also not related to certain data. The data consists of (sha-1 hash (20 bytes) -> bytes from multiple long values (8-24 bytes)) pairs.

Also, previously, I tried with Redis 3.2.3 and the same crash occurred (if it can help, crash report on Redis 3.2.3)

Memory test no errors found.

REDIS BUG REPORT

30130:M 21 Nov 05:40:17.964 # Redis 4.0.2 crashed by signal: 11
30130:M 21 Nov 05:40:17.964 # Crashed running the instuction at: 0x4283a0
30130:M 21 Nov 05:40:17.964 # Accessing address: 0x7fa56ede74d8
30130:M 21 Nov 05:40:17.964 # Failed assertion: (:0)

------ STACK TRACE ------
EIP:
/home/astappev/redis-4.0.2/src/redis-server *:6389(dictAddRaw+0x150)[0x4283a0]

Backtrace:
/home/astappev/redis-4.0.2/src/redis-server *:6389(logStackTrace+0x29)[0x467d89]
/home/astappev/redis-4.0.2/src/redis-server *:6389(sigsegvHandler+0xac)[0x46842c]
/lib64/libpthread.so.0(+0xf5e0)[0x7fdd23dd05e0]
/home/astappev/redis-4.0.2/src/redis-server *:6389(dictAddRaw+0x150)[0x4283a0]
/home/astappev/redis-4.0.2/src/redis-server *:6389(dictAdd+0x11)[0x428451]
/home/astappev/redis-4.0.2/src/redis-server *:6389(dbAdd+0x25)[0x440905]
/home/astappev/redis-4.0.2/src/redis-server *:6389(setKey+0x55)[0x440d75]
/home/astappev/redis-4.0.2/src/redis-server *:6389(setGenericCommand+0x98)[0x44bd18]
/home/astappev/redis-4.0.2/src/redis-server *:6389(setCommand+0xff)[0x44bf2f]
/home/astappev/redis-4.0.2/src/redis-server *:6389(call+0x9e)[0x42bf4e]
/home/astappev/redis-4.0.2/src/redis-server *:6389(processCommand+0x367)[0x42c607]
/home/astappev/redis-4.0.2/src/redis-server *:6389(processInputBuffer+0x105)[0x43b675]
/home/astappev/redis-4.0.2/src/redis-server *:6389(aeProcessEvents+0x23d)[0x42673d]
/home/astappev/redis-4.0.2/src/redis-server *:6389(aeMain+0x2b)[0x426a1b]
/home/astappev/redis-4.0.2/src/redis-server *:6389(main+0x49f)[0x42389f]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7fdd23a1fc05]
/home/astappev/redis-4.0.2/src/redis-server *:6389[0x423b92]

------ INFO OUTPUT ------

Server

redis_version:4.0.2
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:c21bd5031a1bb62c
redis_mode:standalone
os:Linux 3.10.0-514.16.1.el7.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:4.8.5
process_id:30130
run_id:eac381772afb29f628f2dbe9d2b22b0083039c7e
tcp_port:6389
uptime_in_seconds:23286
uptime_in_days:0
hz:10
lru_clock:1289777
executable:/home/astappev/redis-4.0.2/src/redis-server
config_file:

Clients

connected_clients:1
client_longest_output_list:0
client_biggest_input_buf:767
blocked_clients:0

Memory

used_memory:226926628616
used_memory_human:211.34G
used_memory_rss:197138104320
used_memory_rss_human:183.60G
used_memory_peak:226926628616
used_memory_peak_human:211.34G
used_memory_peak_perc:117.84%
used_memory_overhead:137439490190
used_memory_startup:486968
used_memory_dataset:89487138426
used_memory_dataset_perc:39.43%
total_system_memory:811160305664
total_system_memory_human:755.45G
used_memory_lua:37888
used_memory_lua_human:37.00K
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
mem_fragmentation_ratio:0.87
mem_allocator:jemalloc-4.0.3
active_defrag_running:0
lazyfree_pending_objects:0

Persistence

loading:0
rdb_changes_since_last_save:2147484828
rdb_bgsave_in_progress:0
rdb_last_save_time:1511215931
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:0
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_last_write_status:ok
aof_last_cow_size:0

Stats

total_connections_received:1
total_commands_processed:2147484830
instantaneous_ops_per_sec:120210
total_net_input_bytes:128495482874
total_net_output_bytes:10737424140
instantaneous_input_kbps:7029.54
instantaneous_output_kbps:586.96
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0

Replication

role:master
connected_slaves:0
master_replid:3473998b0b7a2d9cfe3f398ed217846d626f8925
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

CPU

used_cpu_sys:12808.08
used_cpu_user:5627.05
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Commandstats

cmdstat_set:calls=2147484828,usec=5183667981,usec_per_call=2.41
cmdstat_select:calls=1,usec=7,usec_per_call=7.00
cmdstat_flushdb:calls=1,usec=4,usec_per_call=4.00

Cluster

cluster_enabled:0

Keyspace

db2:keys=2147483651,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------
id=2 addr=127.0.0.1:38340 fd=8 name= age=23268 idle=0 flags=N db=2 sub=0 psub=0 multi=-1 qbuf=767 qbuf-free=32001 obl=10 oll=0 omem=0 events=r cmd=set

------ CURRENT CLIENT INFO ------
id=2 addr=127.0.0.1:38340 fd=8 name= age=23268 idle=0 flags=N db=2 sub=0 psub=0 multi=-1 qbuf=767 qbuf-free=32001 obl=10 oll=0 omem=0 events=r cmd=set
argv[0]: 'SET'
▒▒▒▒▒�▒▒2D↓▒▒E▒▒▒▒'
argv[2]: ''

------ REGISTERS ------
30130:M 21 Nov 05:40:17.965 #
RAX:00007fa56ede74d8 RBX:00007faf337d0e69
RCX:00007fdd1ce0e220 RDX:0000000000000002
RDI:0000000000004041 RSI:00007faf33600000
RBP:00007faf337d0e80 RSP:00007fff15240f50
R8 :0000000000000002 R9 :0000000000000002
R10:0000000000000018 R11:000000000000005f
R12:00007fdd1ce18690 R13:ffffffffc76fce9b
R14:0000000000000000 R15:00007fdd1ce18660
RIP:00000000004283a0 EFL:0000000000010202
CSGSFS:0000000000000033
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5f) -> 00007fdd1ce2f118
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5e) -> 00007fdd1ceae070
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5d) -> 0000000000440905
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5c) -> 00007fdd1ceae070
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5b) -> 00007fdd1ce2f118
30130:M 21 Nov 05:40:17.965 # (00007fff15240f5a) -> 00007faf337d1a80
30130:M 21 Nov 05:40:17.965 # (00007fff15240f59) -> 0000000000428451
30130:M 21 Nov 05:40:17.965 # (00007fff15240f58) -> 000000000000000f
30130:M 21 Nov 05:40:17.965 # (00007fff15240f57) -> 00007faf337d1a80
30130:M 21 Nov 05:40:17.965 # (00007fff15240f56) -> 0000000000000000
30130:M 21 Nov 05:40:17.965 # (00007fff15240f55) -> 00007faf337d1a80
30130:M 21 Nov 05:40:17.965 # (00007fff15240f54) -> 00007fdd1ce2f118
30130:M 21 Nov 05:40:17.965 # (00007fff15240f53) -> 00007fdd1ce18660
30130:M 21 Nov 05:40:17.965 # (00007fff15240f52) -> 0000000000000000
30130:M 21 Nov 05:40:17.965 # (00007fff15240f51) -> 00007fdd1ce186a0
30130:M 21 Nov 05:40:17.965 # (00007fff15240f50) -> c76fce9b00000016

------ FAST MEMORY TEST ------
30130:M 21 Nov 05:40:17.970 # Bio thread for job type #0 terminated
30130:M 21 Nov 05:40:17.970 # Bio thread for job type #1 terminated
30130:M 21 Nov 05:40:17.970 # Bio thread for job type #2 terminated
*** Preparing to test memory region 744000 (98304 bytes)
*** Preparing to test memory region 203c000 (135168 bytes)
*** Preparing to test memory region 7fa732e00000 (2097152 bytes)
*** Preparing to test memory region 7fa733400000 (231525580800 bytes)
*** Preparing to test memory region 7fdd1b5fe000 (8388608 bytes)
*** Preparing to test memory region 7fdd1bdff000 (8388608 bytes)
*** Preparing to test memory region 7fdd1c600000 (10485760 bytes)
*** Preparing to test memory region 7fdd23600000 (2097152 bytes)
*** Preparing to test memory region 7fdd23dbc000 (20480 bytes)
*** Preparing to test memory region 7fdd23fd9000 (16384 bytes)
*** Preparing to test memory region 7fdd246e5000 (16384 bytes)
*** Preparing to test memory region 7fdd24701000 (12288 bytes)
*** Preparing to test memory region 7fdd24706000 (4096 bytes)
.O.O.O.O.O.O.O.O.O.O.O.O.O
Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.

------ DUMPING CODE AROUND EIP ------
Symbol: dictAddRaw (base: 0x428250)
Module: /home/astappev/redis-4.0.2/src/redis-server *:6389 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x428250 -D -b binary -m i386:x86-64 /tmp/dump.bin

30130:M 21 Nov 05:53:39.869 # dump of function (hexdump of 464 bytes):
41574989ff415641554154554889d5534889f34883ec1848837f50ff740b48837f58000f8487010000498b074889dfff104885ed89442404740848c745000000000049837f50ff7477498d47404d89fc4889442408448b6c240445236c2420498b4424104489ea4c8b34d04d85f6752ae99b0000000f1f00498b07488b40184885c0740d498b7f084889deffd085c075114d8b76104d85f67476498b164839d375d64885ed74044c8975004883c41831c05b5d415c415d415e415fc30f1f4000498b4f184885c90f84f2000000498b77284839f10f876fffffff8b05d473310085c0751231d24889f048f7f14883f8050f8653ffffff4801f64c89ffe81ffaffff83f8010f853fffffffeb9f0f1f400049837f50ff0f84b60000004983c4204c3b6424080f852bffffff4183fdff0f8477ffffff4d8d6730bf180000004d63ede81ba600004889c5498b04244a8d04e8488b1048895510488928498b07498344241801488b40084885c07424498b7f084889deffd0488945004883c4184889e85b5d415c415d415e415fc30f1f44000048895d004883c4184889e85b5d415c415d415e415fc3662e0f1f840000000000be01000000e866faffffe96afeffffbe040000004c89ffe854f9ffffe930ffff
Function at 0x427d70 is dictExpand
Function at 0x4329b0 is zmalloc
Function at 0x427e70 is dictRehash
Function at 0x427d70 is dictExpand

[soloestoy]

Bug located, notice that db2's keys is 2147483651 out of 31 bits of int, but dictAddRaw use int as index, so when index's value is larger than 2^31-1, it can be negative:

dictEntry *dictAddRaw(dict *d, void *key, dictEntry **existing)
{
    int index;
    dictEntry *entry;
    dictht *ht;

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

    /* Get the index of the new element, or -1 if
     * the element already exists. */
    if ((index = _dictKeyIndex(d, key, dictHashKey(d,key), existing)) == -1)
        return NULL;

    /* Allocate the memory and store the new entry.
     * Insert the element in top, with the assumption that in a database
     * system it is more likely that recently added entries are accessed
     * more frequently. */
    ht = dictIsRehashing(d) ? &d->ht[1] : &d->ht[0];
    entry = zmalloc(sizeof(*entry));
    entry->next = ht->table[index];
    ht->table[index] = entry;
    ht->used++;

    /* Set the hash entry fields. */
    dictSetKey(d, entry, key);
    return entry;
}

And some other functions also have the problem, fix it in PR #4494 .

BTW, I think there are still many potential int problems about other types set/zset/list..., and we should fix them carefully, maybe in next version Redis 4.0.4 @antirez

[soloestoy]

Unfortunately, quicklist has the int problem too:

typedef struct quicklist {
    quicklistNode *head;
    quicklistNode *tail;
    unsigned long count;        /* total count of all entries in all ziplists */
    unsigned int len;           /* number of quicklistNodes */
    int fill : 16;              /* fill factor for individual nodes */
    unsigned int compress : 16; /* depth of end nodes not to compress;0=off */
} quicklist;

unsigned int quicklistCount(const quicklist *ql);

The count in quicklist is unsigned long, but the return value of quicklistCount is unsigned int, so if the count is larger than unsigned int it may be casted to 0, and will be mis deleted by *POP:

unsigned long listTypeLength(const robj *subject) {
    if (subject->encoding == OBJ_ENCODING_QUICKLIST) {
        return quicklistCount(subject->ptr);
    } else {
        serverPanic("Unknown list encoding");
    }
}

void popGenericCommand(client *c, int where) {
...
        if (listTypeLength(o) == 0) {
            notifyKeyspaceEvent(NOTIFY_GENERIC,"del",
                                c->argv[1],c->db->id);
            dbDelete(c->db,c->argv[1]);
        }
...
}

Fix it in 58a6e1b, please check @antirez . And should we change quicklist->len to unsigned long? The len may be out of unsigned int I think.

BTW, now I understand the why zero-length list could appear in issue #4409

[soloestoy]

Now, I confirm that we should change quicklist->len to unsigned long, just see the experiment below:

1. Firstly I use redis-benchmark to call lpush:

   $redis-benchmark -t lpush -d 10000 -q
   

   And every element's length is 10000 larger than the SIZE_SAFETY_LIMIT:

   /* Maximum size in bytes of any multi-element ziplist.
    * Larger values will live in their own isolated ziplists. */
   #define SIZE_SAFETY_LIMIT 8192
   

2. Then, use redis-cli to get the len and count of quicklist:

   $redis-cli
   127.0.0.1:6379> llen mylist
   (integer) 100000
   127.0.0.1:6379> debug object mylist
   Value at:0x7f4c07e6a4d0 refcount:1 encoding:quicklist serializedlength:13700005 lru:2324694 
   lru_seconds_idle:7 ql_nodes:100000 ql_avg_node:1.00 ql_ziplist_max:-2 ql_compressed:0 
   ql_uncompressed_size:1001400000
   

Now, we can see that, len and count are same, so we should change quicklist->len to unsigned long, fix it in 7649748, please check @antirez

[astappiev]

Thank you very much, I can confirm that using a version of PR #4494 solved my problem.

[soloestoy]

Notice that used_memory_overhead:137439490190 is almost 128GB, it's too huge, so I open another issue #4504 to discuss it.

[antirez]

I'm closing this since I merged both the list and dict.c patches from @soloestoy... leaving the other issue open for further discussions.