redis crashed when large amount of key expired or highly ops with command setex

[treemanzhou]

=== REDIS BUG REPORT START: Cut & paste starting from here ===
6542:M 12 Feb 14:28:01.653 # Redis 4.0.12 crashed by signal: 11
6542:M 12 Feb 14:28:01.653 # Crashed running the instruction at: 0x497ef8
6542:M 12 Feb 14:28:01.653 # Accessing address: 0x7f6de3c00000
6542:M 12 Feb 14:28:01.653 # Failed assertion: (:0)

------ STACK TRACE ------
EIP:
/usr/local/redis-server4/bin/redis-server *:9160(siphash+0x58)[0x497ef8]

Backtrace:
/usr/local/redis/bin/redis-server *:9160(logStackTrace+0x3c)[0x46800c]
/usr/local/redis/bin/redis-server *:9160(sigsegvHandler+0xa3)[0x469243]
/lib64/libpthread.so.0[0x3f3000f710]
/usr/local/redis/bin/redis-server *:9160(siphash+0x58)[0x497ef8]
/usr/local/redis/bin/redis-server *:9160(dictRehash+0x8d)[0x427cad]
/usr/local/redis/bin/redis-server *:9160(dictAddRaw+0x1aa)[0x4287aa]
/usr/local/redis/bin/redis-server *:9160(dictAdd+0x20)[0x428900]
/usr/local/redis/bin/redis-server *:9160(dbAdd+0x6a)[0x44281a]
/usr/local/redis/bin/redis-server *:9160(setKey+0x76)[0x442b26]
/usr/local/redis/bin/redis-server *:9160(setGenericCommand+0xa4)[0x44cfa4]
/usr/local/redis/bin/redis-server *:9160(setCommand+0xfa)[0x44d32a]
/usr/local/redis/bin/redis-server *:9160(call+0x87)[0x429d57]
/usr/local/redis/bin/redis-server *:9160(processCommand+0x395)[0x42e885]
/usr/local/redis/bin/redis-server *:9160(processInputBuffer+0x10d)[0x43a92d]
/usr/local/redis/bin/redis-server *:9160(aeProcessEvents+0x1d3)[0x425453]
/usr/local/redis/bin/redis-server *:9160(aeMain+0x2b)[0x42577b]
/usr/local/redis/bin/redis-server *:9160(main+0x500)[0x42dfc0]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x3f2fc1ed5d]
/usr/local/redis/bin/redis-server *:9160[0x422ae9]

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

Server

redis_version:4.0.12
redis_git_sha1:afc4b36c
redis_git_dirty:1
redis_build_id:7b7e61a779d11458
redis_mode:standalone
os:Linux 4.9.0 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:sync-builtin
gcc_version:4.4.7
process_id:6542
run_id:d8be1f27b0ac6724ababc1f90ccfb942a30ff154
tcp_port:9160
uptime_in_seconds:968853
uptime_in_days:11
hz:90
lru_clock:6449008
executable:/usr/local/redis-server4/bin/redis-server
config_file:/usr/local/redis-server4/conf/9160.conf

Clients

connected_clients:75
client_longest_output_list:0
client_biggest_input_buf:176
blocked_clients:0

Memory

used_memory:3819247272
used_memory_human:3.56G
used_memory_rss:5437214720
used_memory_rss_human:5.06G
used_memory_peak:5366974024
used_memory_peak_human:5.00G
used_memory_peak_perc:71.16%
used_memory_overhead:1766956702
used_memory_startup:2535928
used_memory_dataset:2052290570
used_memory_dataset_perc:53.77%
total_system_memory:270393511936
total_system_memory_human:251.82G
used_memory_lua:37888
used_memory_lua_human:37.00K
maxmemory:5368709120
maxmemory_human:5.00G
maxmemory_policy:allkeys-lfu
mem_fragmentation_ratio:1.42
mem_allocator:jemalloc-4.0.3
active_defrag_running:35
lazyfree_pending_objects:0

Persistence

loading:0
rdb_changes_since_last_save:558693402
rdb_bgsave_in_progress:0
rdb_last_save_time:1548984027
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:204952
total_commands_processed:570466897
instantaneous_ops_per_sec:8176
total_net_input_bytes:43348193139
total_net_output_bytes:7715628701
instantaneous_input_kbps:534.14
instantaneous_output_kbps:52.41
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
evicted_keys:0
keyspace_hits:148508
keyspace_misses:184542
pubsub_channels:1
pubsub_patterns:0
latest_fork_usec:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:290070812
active_defrag_misses:72104321870
active_defrag_key_hits:277549012
active_defrag_key_misses:17826527715

Replication

role:master
connected_slaves:0
master_replid:745b534f291aefce66f261f74db1021be88ae267
master_replid2:57fa1bf603ea7401693064552a5b5a36c5764e81
master_repl_offset:64451683007
second_repl_offset:64431136599
repl_backlog_active:1
repl_backlog_size:10485760
repl_backlog_first_byte_offset:64441197248
repl_backlog_histlen:10485760

CPU

used_cpu_sys:4617.95
used_cpu_user:33581.44
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Commandstats

cmdstat_set:calls=416268148,usec=1590024558,usec_per_call=3.82
cmdstat_unlink:calls=142298377,usec=834018196,usec_per_call=5.86
cmdstat_del:calls=126877,usec=298214,usec_per_call=2.35
cmdstat_multi:calls=3,usec=0,usec_per_call=0.00
cmdstat_exec:calls=12,usec=5182,usec_per_call=431.83
cmdstat_get:calls=333050,usec=479216,usec_per_call=1.44
cmdstat_slowlog:calls=1,usec=3,usec_per_call=3.00
cmdstat_config:calls=587034,usec=11468684,usec_per_call=19.54
cmdstat_select:calls=61,usec=18,usec_per_call=0.30
cmdstat_client:calls=232,usec=432,usec_per_call=1.86
cmdstat_subscribe:calls=140,usec=522,usec_per_call=3.73
cmdstat_ping:calls=4557282,usec=3443124,usec_per_call=0.76
cmdstat_publish:calls=5136295,usec=28271578,usec_per_call=5.50
cmdstat_info:calls=1159385,usec=86987255,usec_per_call=75.03

Cluster

cluster_enabled:0

Keyspace

db0:keys=18995004,expires=18994446,avg_ttl=77558303

------ CURRENT CLIENT INFO ------
id=204874 addr=10.27.4.206:63143 fd=19 name= age=102 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=176 qbuf-free=32592 obl=0 oll=0 omem=0 events=r cmd=set
argv[0]: 'set'
argv[1]: '85F3CC4E-E512-4918-8825-0DE7FA3D800B_4633'
argv[2]: '7'
argv[3]: 'ex'
argv[4]: '86400'
6542:M 12 Feb 14:28:01.654 # key '85F3CC4E-E512-4918-8825-0DE7FA3D800B_4633' found in DB containing the following object:
6542:M 12 Feb 14:28:01.654 # Object type: 0
6542:M 12 Feb 14:28:01.654 # Object encoding: 1
6542:M 12 Feb 14:28:01.654 # Object refcount: 1

------ REGISTERS ------
6542:M 12 Feb 14:28:01.654 #
RAX:ffbad0b046eeab66 RBX:00007f6de63685a0
RCX:0000000000000000 RDX:d24a99930cac3fb4
RDI:00007f6de3bffff9 RSI:ffffffffaea3ff28
RBP:00007f6d88674a10 RSP:00007ffc12aa1568
R8 :0fb591aedb7847e7 R9 :6d73f24dc5dc4af5
R10:00007f6d0e61cf51 R11:2800000000000000
R12:000000000000000a R13:00007f6cbc71b818
R14:0000000000000000 R15:0000000000000000
RIP:0000000000497ef8 EFL:0000000000010293
CSGSFS:002b000000000033
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1577) -> 00007f6d65d3d578
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1576) -> 00007f6db35e9053
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1575) -> 00000000599e7900
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1574) -> 00007f6de63685a0
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1573) -> 0000000000000018
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1572) -> 00007f6de56e4a40
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1571) -> c057b044f461be26
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1570) -> 00000000030df130
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156f) -> 00007f6d65d3d578
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156e) -> 00000000004287aa
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156d) -> 0000000000000000
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156c) -> 0000000000000000
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156b) -> 00007f6db35e9053
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa156a) -> 00007f6de63685a0
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1569) -> 00007f6de63685a0
6542:M 12 Feb 14:28:01.654 # (00007ffc12aa1568) -> 0000000000427cad

------ FAST MEMORY TEST ------
6542:M 12 Feb 14:28:01.655 # Bio thread for job type #0 terminated
6542:M 12 Feb 14:28:01.655 # Bio thread for job type #1 terminated
6542:M 12 Feb 14:28:01.655 # Bio thread for job type #2 terminated
*** Preparing to test memory region 74e000 (98304 bytes)
*** Preparing to test memory region 18c9000 (135168 bytes)
*** Preparing to test memory region 3f2f621000 (4096 bytes)
*** Preparing to test memory region 3f2ff8f000 (20480 bytes)
*** Preparing to test memory region 3f30219000 (16384 bytes)
*** Preparing to test memory region 7f6c63600000 (6448742400 bytes)
*** Preparing to test memory region 7f6de3dfe000 (8388608 bytes)
*** Preparing to test memory region 7f6de45ff000 (8388608 bytes)
*** Preparing to test memory region 7f6de4e00000 (10485760 bytes)
*** Preparing to test memory region 7f6de5a00000 (8388608 bytes)
*** Preparing to test memory region 7f6de6200000 (2097152 bytes)
*** Preparing to test memory region 7f6dec400000 (2097152 bytes)
*** Preparing to test memory region 7f6dec71b000 (16384 bytes)
*** Preparing to test memory region 7f6dec733000 (4096 bytes)
*** Preparing to test memory region 7f6dec734000 (4096 bytes)
.O.O.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: siphash (base: 0x497ea0)
Module: /usr/local/redis/bin/redis-server *:9160 (base 0x400000)
$ xxd -r -p /tmp/dump.hex /tmp/dump.bin
$ objdump --adjust-vma=0x497ea0 -D -b binary -m i386:x86-64 /tmp/dump.bin

6542:M 12 Feb 14:28:23.488 # dump of function (hexdump of 216 bytes):
4c8b42084989f2488b0a4983e2f848ba736574796264657448b86d6f646e61726f644e8d14174989f349b96172656e6567796c4c31c24c31c049b875657370656d6f7349c1e3384931c94931c84c39d7744b660f1f440000488b0f4e8d040048c1c8334883c7084c31c049c1c8204831ca4e8d0c0a48c1ca304c31ca4901c148
c1c82f4e8d040248c1ca2b4c31c849c1c9204c31c24931c84939fa75bb83e607ff24f5787a5100660f1f840000000000410fb64a0648c1e1304909cb410fb64a0548c1e1284909cb410fb64a0448c1e1204909cb410fb64a

=== REDIS BUG REPORT END. Make sure to include from START to END. ===

   Please report the crash by opening an issue on github:

       http://github.com/antirez/redis/issues

Suspect RAM error? Use redis-server --test-memory to verify it.