Redis: Redis Crash Report

[danielamaya]

I am using Jedis library (Java) which takes an input file and does an incr(file_line) using a Pipeline. There's no multithreading involved. A simple read of the file, and for each line incr(file_line). The file has ~5 billion lines. At the point of around 2.5 billion lines, Redis crashes with the following error. This happened on a server with 488GB of memory, and again after Redis to a server with 976GB of memory. I'm pretty sure at this point that memory limitations are not the issue. It seems at a certain point with a large amount of keys, Redis simply crashes under the load.

Here's the output from the log file:

=== REDIS BUG REPORT START: Cut & paste starting from here ===
2799:M 29 Jan 18:04:28.360 # ------------------------------------------------
2799:M 29 Jan 18:04:28.360 # !!! Software Failure. Press left mouse button to continue
2799:M 29 Jan 18:04:28.360 # Guru Meditation: "decrRefCount against refcount <= 0" #object.c:305
2799:M 29 Jan 18:04:28.360 # (forcing SIGSEGV in order to print the stack trace)
2799:M 29 Jan 18:04:28.360 # ------------------------------------------------
2799:M 29 Jan 18:04:28.360 #     Redis 3.0.6 crashed by signal: 11
2799:M 29 Jan 18:04:28.360 #     SIGSEGV caused by address: 0xffffffffffffffff
2799:M 29 Jan 18:04:28.360 #     Failed assertion: <no assertion failed> (<no file>:0)
2799:M 29 Jan 18:04:28.360 # --- STACK TRACE
/usr/bin/redis-server 127.0.0.1:6379(logStackTrace+0xa6)[0x55cc9c80eda6]
/usr/bin/redis-server 127.0.0.1:6379(_redisPanic+0x84)[0x55cc9c80dd44]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fa5db75b390]
/usr/bin/redis-server 127.0.0.1:6379(_redisPanic+0x84)[0x55cc9c80dd44]
/usr/bin/redis-server 127.0.0.1:6379(decrRefCount+0xca)[0x55cc9c7e9f9a]
/usr/bin/redis-server 127.0.0.1:6379(hincrbyCommand+0xf4)[0x55cc9c8021f4]
/usr/bin/redis-server 127.0.0.1:6379(call+0x8e)[0x55cc9c7dae1e]
/usr/bin/redis-server 127.0.0.1:6379(processCommand+0x3ff)[0x55cc9c7ddf3f]
/usr/bin/redis-server 127.0.0.1:6379(processInputBuffer+0x4f)[0x55cc9c7e850f]
/usr/bin/redis-server 127.0.0.1:6379(readQueryFromClient+0xb2)[0x55cc9c7e8652]
/usr/bin/redis-server 127.0.0.1:6379(aeProcessEvents+0x137)[0x55cc9c7d5297]
/usr/bin/redis-server 127.0.0.1:6379(aeMain+0x2b)[0x55cc9c7d55fb]
/usr/bin/redis-server 127.0.0.1:6379(main+0x364)[0x55cc9c7d4274]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fa5db3a0830]
/usr/bin/redis-server 127.0.0.1:6379(_start+0x29)[0x55cc9c7d43e9]
2799:M 29 Jan 18:04:28.360 # --- INFO OUTPUT
2799:M 29 Jan 18:04:28.360 # # Server
redis_version:3.0.6
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:687a2a319020fa42
redis_mode:standalone
os:Linux 4.4.0-1047-aws x86_64
arch_bits:64
multiplexing_api:epoll
gcc_version:5.3.1
process_id:2799
run_id:6bda438bb6f1b07c267a4093b924b612bd6905cc
tcp_port:6379
uptime_in_seconds:12775
uptime_in_days:0
hz:10
lru_clock:7299628
config_file:/etc/redis/redis.conf

# Clients
connected_clients:1
client_longest_output_list:507
client_biggest_input_buf:9006
blocked_clients:0

# Memory
used_memory:366138778256
used_memory_human:340.99G
used_memory_rss:373365194752
used_memory_peak:366138778256
used_memory_peak_human:340.99G
used_memory_lua:36864
mem_fragmentation_ratio:1.02
mem_allocator:jemalloc-3.6.0

# Persistence
loading:0
rdb_changes_since_last_save:2213903435
rdb_bgsave_in_progress:0
rdb_last_save_time:1517236293
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
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

# Stats
total_connections_received:8
total_commands_processed:2213903451
instantaneous_ops_per_sec:315000
total_net_input_bytes:279351350806
total_net_output_bytes:24799028627
instantaneous_input_kbps:38950.00
instantaneous_output_kbps:0.00
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

# Replication
role:master
connected_slaves:0
master_repl_offset:0
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:1037.94
used_cpu_user:5370.20
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

# Commandstats
cmdstat_hincrby:calls=2213903434,usec=4040452870,usec_per_call=1.83
cmdstat_flushall:calls=1,usec=7,usec_per_call=7.00
cmdstat_info:calls=9,usec=217,usec_per_call=24.11
cmdstat_config:calls=7,usec=98,usec_per_call=14.00

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=63,expires=0,avg_ttl=0
hash_init_value: 1516552667

2799:M 29 Jan 18:04:28.360 # --- CLIENT LIST OUTPUT
2799:M 29 Jan 18:04:28.360 # id=3 addr=127.0.0.1:55606 fd=5 name= age=6916 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=9006 qbuf-free=23868 obl=16381 oll=507 omem=12185561 events=rw cmd=hincrby

2799:M 29 Jan 18:04:28.360 # --- CURRENT CLIENT INFO
2799:M 29 Jan 18:04:28.360 # client: id=3 addr=127.0.0.1:55606 fd=5 name= age=6916 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=9006 qbuf-free=23868 obl=16381 oll=507 omem=12185561 events=rw cmd=hincrby
2799:M 29 Jan 18:04:28.360 # argv[0]: 'HINCRBY'
2799:M 29 Jan 18:04:28.360 # argv[1]: '"K'
2799:M 29 Jan 18:04:28.360 # argv[2]: '"Kinderopvang'
2799:M 29 Jan 18:04:28.361 # argv[3]: '1'
2799:M 29 Jan 18:04:28.361 # key '"K' found in DB containing the following object:
2799:M 29 Jan 18:04:28.361 # Object type: 4
2799:M 29 Jan 18:04:28.361 # Object encoding: 2
2799:M 29 Jan 18:04:28.361 # Object refcount: 1
2799:M 29 Jan 18:04:28.361 # Hash size: 40401633
2799:M 29 Jan 18:04:28.361 # --- REGISTERS
2799:M 29 Jan 18:04:28.361 #
RAX:0000000000000000 RBX:000055cc9c8502f8
RCX:00007fa5dbb9d370 RDX:0000000000000002
RDI:00007fa5da806000 RSI:00000000000000e5
RBP:000055cc9c8501ae RSP:00007ffe7e14a870
R8 :00007fa5dc0c0740 R9 :00007fa5dc0c0740
R10:0000000000000030 R11:0000000000000246
R12:0000000000000131 R13:0000000083f57c4b
R14:0000000000000007 R15:000563ee13c16239
RIP:000055cc9c80dd44 EFL:0000000000010202
CSGSFS:0000000000000033
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87f) -> 0000000000057f39
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87e) -> 000000005a6f622c
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87d) -> 000055cc9c7dae1e
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87c) -> 0000000000000000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87b) -> 0000000000000000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87a) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a879) -> af205f16450d2400
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a878) -> 0000000000000001
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a877) -> 0000000000000001
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a876) -> 0000000000000080
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a875) -> 000055cc9c8021f4
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a874) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a873) -> 000055cc9c7e9f9a
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a872) -> 00007fa5da861390
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a871) -> 00007fa5da8d1670
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a870) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # --- FAST MEMORY TEST
2799:M 29 Jan 18:04:28.361 # Bio thread for job type #0 terminated
2799:M 29 Jan 18:04:28.361 # Bio thread for job type #1 terminated

[antirez]

Hello, this could be due to an hash table bug we fixed related to reaching
2 billions elements. Please try again with 4.0.7 and if possible report
back. Thanks for your contribution.

Il 29 Gen 2018 8:02 PM, "Daniel" [e-mail] ha scritto:

I am using Jedis library (Java) which takes an input file and does an
incr(file_line) using a Pipeline. There's no multithreading involved. A
simple read of the file, and for each line incr(file_line). The file has
~5 billion lines. At the point of around 2.5 billion lines, Redis crashes
with the following error. This happened on a server with 488GB of memory,
and again after Redis to a server with 976GB of memory. I'm pretty sure at
this point that memory limitations are not the issue. It seems at a certain
point with a large amount of keys, Redis simply crashes under the load.

Here's the output from the log file:

=== REDIS BUG REPORT START: Cut & paste starting from here ===
2799:M 29 Jan 18:04:28.360 # ------------------------------------------------
2799:M 29 Jan 18:04:28.360 # !!! Software Failure. Press left mouse button to continue
2799:M 29 Jan 18:04:28.360 # Guru Meditation: "decrRefCount against refcount <= 0" #object.c:305
2799:M 29 Jan 18:04:28.360 # (forcing SIGSEGV in order to print the stack trace)
2799:M 29 Jan 18:04:28.360 # ------------------------------------------------
2799:M 29 Jan 18:04:28.360 # Redis 3.0.6 crashed by signal: 11
2799:M 29 Jan 18:04:28.360 # SIGSEGV caused by address: 0xffffffffffffffff
2799:M 29 Jan 18:04:28.360 # Failed assertion: (:0)
2799:M 29 Jan 18:04:28.360 # --- STACK TRACE
/usr/bin/redis-server 127.0.0.1:6379(logStackTrace+0xa6)[0x55cc9c80eda6]
/usr/bin/redis-server 127.0.0.1:6379(_redisPanic+0x84)[0x55cc9c80dd44]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fa5db75b390]
/usr/bin/redis-server 127.0.0.1:6379(_redisPanic+0x84)[0x55cc9c80dd44]
/usr/bin/redis-server 127.0.0.1:6379(decrRefCount+0xca)[0x55cc9c7e9f9a]
/usr/bin/redis-server 127.0.0.1:6379(hincrbyCommand+0xf4)[0x55cc9c8021f4]
/usr/bin/redis-server 127.0.0.1:6379(call+0x8e)[0x55cc9c7dae1e]
/usr/bin/redis-server 127.0.0.1:6379(processCommand+0x3ff)[0x55cc9c7ddf3f]
/usr/bin/redis-server 127.0.0.1:6379(processInputBuffer+0x4f)[0x55cc9c7e850f]
/usr/bin/redis-server 127.0.0.1:6379(readQueryFromClient+0xb2)[0x55cc9c7e8652]
/usr/bin/redis-server 127.0.0.1:6379(aeProcessEvents+0x137)[0x55cc9c7d5297]
/usr/bin/redis-server 127.0.0.1:6379(aeMain+0x2b)[0x55cc9c7d55fb]
/usr/bin/redis-server 127.0.0.1:6379(main+0x364)[0x55cc9c7d4274]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fa5db3a0830]
/usr/bin/redis-server 127.0.0.1:6379(_start+0x29)[0x55cc9c7d43e9]
2799:M 29 Jan 18:04:28.360 # --- INFO OUTPUT
2799:M 29 Jan 18:04:28.360 # # Server
redis_version:3.0.6
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:687a2a319020fa42
redis_mode:standalone
os:Linux 4.4.0-1047-aws x86_64
arch_bits:64
multiplexing_api:epoll
gcc_version:5.3.1
process_id:2799
run_id:6bda438bb6f1b07c267a4093b924b612bd6905cc
tcp_port:6379
uptime_in_seconds:12775
uptime_in_days:0
hz:10
lru_clock:7299628
config_file:/etc/redis/redis.conf

Clients

connected_clients:1
client_longest_output_list:507
client_biggest_input_buf:9006
blocked_clients:0

Memory

used_memory:366138778256
used_memory_human:340.99G
used_memory_rss:373365194752
used_memory_peak:366138778256
used_memory_peak_human:340.99G
used_memory_lua:36864
mem_fragmentation_ratio:1.02
mem_allocator:jemalloc-3.6.0

Persistence

loading:0
rdb_changes_since_last_save:2213903435
rdb_bgsave_in_progress:0
rdb_last_save_time:1517236293
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
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

Stats

total_connections_received:8
total_commands_processed:2213903451
instantaneous_ops_per_sec:315000
total_net_input_bytes:279351350806
total_net_output_bytes:24799028627
instantaneous_input_kbps:38950.00
instantaneous_output_kbps:0.00
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

Replication

role:master
connected_slaves:0
master_repl_offset:0
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

CPU

used_cpu_sys:1037.94
used_cpu_user:5370.20
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Commandstats

cmdstat_hincrby:calls=2213903434,usec=4040452870,usec_per_call=1.83
cmdstat_flushall:calls=1,usec=7,usec_per_call=7.00
cmdstat_info:calls=9,usec=217,usec_per_call=24.11
cmdstat_config:calls=7,usec=98,usec_per_call=14.00

Cluster

cluster_enabled:0

Keyspace

db0:keys=63,expires=0,avg_ttl=0
hash_init_value: 1516552667

2799:M 29 Jan 18:04:28.360 # --- CLIENT LIST OUTPUT
2799:M 29 Jan 18:04:28.360 # id=3 addr=127.0.0.1:55606 fd=5 name= age=6916 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=9006 qbuf-free=23868 obl=16381 oll=507 omem=12185561 events=rw cmd=hincrby

2799:M 29 Jan 18:04:28.360 # --- CURRENT CLIENT INFO
2799:M 29 Jan 18:04:28.360 # client: id=3 addr=127.0.0.1:55606 fd=5 name= age=6916 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=9006 qbuf-free=23868 obl=16381 oll=507 omem=12185561 events=rw cmd=hincrby
2799:M 29 Jan 18:04:28.360 # argv[0]: 'HINCRBY'
2799:M 29 Jan 18:04:28.360 # argv[1]: '"K'
2799:M 29 Jan 18:04:28.360 # argv[2]: '"Kinderopvang'
2799:M 29 Jan 18:04:28.361 # argv[3]: '1'
2799:M 29 Jan 18:04:28.361 # key '"K' found in DB containing the following object:
2799:M 29 Jan 18:04:28.361 # Object type: 4
2799:M 29 Jan 18:04:28.361 # Object encoding: 2
2799:M 29 Jan 18:04:28.361 # Object refcount: 1
2799:M 29 Jan 18:04:28.361 # Hash size: 40401633
2799:M 29 Jan 18:04:28.361 # --- REGISTERS
2799:M 29 Jan 18:04:28.361 #
RAX:0000000000000000 RBX:000055cc9c8502f8
RCX:00007fa5dbb9d370 RDX:0000000000000002
RDI:00007fa5da806000 RSI:00000000000000e5
RBP:000055cc9c8501ae RSP:00007ffe7e14a870
R8 :00007fa5dc0c0740 R9 :00007fa5dc0c0740
R10:0000000000000030 R11:0000000000000246
R12:0000000000000131 R13:0000000083f57c4b
R14:0000000000000007 R15:000563ee13c16239
RIP:000055cc9c80dd44 EFL:0000000000010202
CSGSFS:0000000000000033
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87f) -> 0000000000057f39
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87e) -> 000000005a6f622c
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87d) -> 000055cc9c7dae1e
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87c) -> 0000000000000000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87b) -> 0000000000000000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a87a) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a879) -> af205f16450d2400
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a878) -> 0000000000000001
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a877) -> 0000000000000001
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a876) -> 0000000000000080
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a875) -> 000055cc9c8021f4
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a874) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a873) -> 000055cc9c7e9f9a
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a872) -> 00007fa5da861390
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a871) -> 00007fa5da8d1670
2799:M 29 Jan 18:04:28.361 # (00007ffe7e14a870) -> 00007fa5da931000
2799:M 29 Jan 18:04:28.361 # --- FAST MEMORY TEST
2799:M 29 Jan 18:04:28.361 # Bio thread for job type #0 terminated
2799:M 29 Jan 18:04:28.361 # Bio thread for job type #1 terminated

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/antirez/redis/issues/4639, or mute the thread
https://github.com/notifications/unsubscribe-auth/AAEAYAFMFVbUIJ3g_I1UPuIFUJ0pA-xgks5tPhXigaJpZM4RxL2S
.

[danielamaya]

I pulled 4.0.7 down today and ran the same file again. This time it completed with all 6 billion records added to Redis and no more issues. Thanks antirez!

Here's the code:

import redis.clients.jedis.Jedis;
import redis.clients.jedis.Pipeline;

import java.io.*;

public class CsvToRedis {
    public static void main(String[] args) throws InterruptedException {
        String file = args[0];
        File f = new File(file);
        System.out.println(f.getName());

        Jedis j = new Jedis("localhost", 6379, 100000000);
        j.flushAll();
        Pipeline p = j.pipelined();

        long count = 0;
        try(BufferedReader br = new BufferedReader(new FileReader(file))) {
            for(String line; (line = br.readLine()) != null; ) {
                count++;
                if (count % 1000 == 0) {
                    System.out.println(count);
                    p.sync();
                }
                p.hincrBy(line.substring(0, 2), line, 1);
            }
            p.sync();
        } catch (FileNotFoundException e) {
            e.printStackTrace();
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
}

I will note that when I was running 3.0.6, this code failed when doing a p.incr(line) as well. I decided to modify the behavior and use hashes, hoping that it would fix the issue. It did not. The only thing that fixed the issue was moving to 4.0.7.

[antirez]

Great @danielamaya! Thanks for acknowledging that this is fixed in 4.0.7 :-) Please note that it's fixed only in 4.0.7, for instance 4.0.6 will fail as well.

[odedsCoolScripts]

Hi @antirez,

Can you please tell if this is the same issue here?

:M 06 Jun 15:10:20.621 # Out Of Memory allocating 3038848 bytes!
1:M 06 Jun 15:10:20.621 #

=== REDIS BUG REPORT START: Cut & paste starting from here ===
1:M 06 Jun 15:10:20.621 # ------------------------------------------------
1:M 06 Jun 15:10:20.621 # !!! Software Failure. Press left mouse button to continue
1:M 06 Jun 15:10:20.622 # Guru Meditation: "Redis aborting for OUT OF MEMORY" #redis.c:3572
1:M 06 Jun 15:10:20.622 # (forcing SIGSEGV in order to print the stack trace)
1:M 06 Jun 15:10:20.622 # ------------------------------------------------
1:M 06 Jun 15:10:20.624 #     Redis 3.0.7 crashed by signal: 11
1:M 06 Jun 15:10:20.624 #     SIGSEGV caused by address: 0xffffffffffffffff
1:M 06 Jun 15:10:20.624 #     Failed assertion: <no assertion failed> (<no file>:0)
1:M 06 Jun 15:10:20.624 # --- STACK TRACE
1:M 06 Jun 15:10:20.676 # --- INFO OUTPUT
1:M 06 Jun 15:10:20.716 # # Server
redis_version:3.0.7
redis_git_sha1:00000000

Thanks a lot,

Oded