KeyDB

KeyDB copied to clipboard

Crash report

TL:DR: Check kernel param: vm.max_map_count and increase it by sysctl or echo (https://github.com/Snapchat/KeyDB/issues/271)

1440383:1200209:C 21 Jun 2022 13:39:09.482 * RDB: 429 MB of memory used by copy-on-write
1200145:1200209:M 21 Jun 2022 13:39:10.393 * Background saving terminated with success
1200145:1200209:M 21 Jun 2022 13:40:11.008 * 100000 changes in 60 seconds. Saving...
1200145:1200209:M 21 Jun 2022 13:40:11.990 * Background saving started by pid 1440849
1440849:1200209:C 21 Jun 2022 13:40:14.001 # Out Of Memory allocating 152365 bytes!


=== KEYDB BUG REPORT START: Cut & paste starting from here ===
1440849:1200209:C 21 Jun 2022 13:40:14.001 # ------------------------------------------------
1440849:1200209:C 21 Jun 2022 13:40:14.001 # !!! Software Failure. Press left mouse button to continue
1440849:1200209:C 21 Jun 2022 13:40:14.001 # Guru Meditation: KeyDB aborting for OUT OF MEMORY. Allocating 152365 bytes! #server.cpp:6412

------ STACK TRACE ------

Backtrace:
keydb-rdb-bgsave 0.0.0.0:6379(redisOutOfMemoryHandler(unsigned long)+0x2a) [0x55d17e459eaa]
keydb-rdb-bgsave 0.0.0.0:6379(zmalloc+0x2e) [0x55d17e46a41e]
keydb-rdb-bgsave 0.0.0.0:6379(+0x9ef39) [0x55d17e49ef39]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveRawString(_rio*, unsigned char const*, unsigned long)+0x54) [0x55d17e49f2c4]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveObject(_rio*, robj_roptr, redisObject*)+0x155) [0x55d17e4a0375]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveKeyValuePair(_rio*, redisObject*, redisObject*, expireEntry*)+0x104) [0x55d17e4a0f74]
keydb-rdb-bgsave 0.0.0.0:6379(saveKey(_rio*, redisDb*, int, unsigned long*, char const*, redisObject*)+0x7b) [0x55d17e4a137b]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveRio(_rio*, int*, int, rdbSaveInfo*)+0x23d) [0x55d17e4a176d]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveFile(char*, rdbSaveInfo*)+0xae) [0x55d17e4a24de]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSave(rdbSaveInfo*)+0x1f) [0x55d17e4a276f]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveBackground(rdbSaveInfo*)+0xbf) [0x55d17e4a285f]
keydb-rdb-bgsave 0.0.0.0:6379(serverCron(aeEventLoop*, long long, void*)+0x6c4) [0x55d17e464ed4]
keydb-rdb-bgsave 0.0.0.0:6379(aeProcessEvents+0x33d) [0x55d17e45554d]
keydb-rdb-bgsave 0.0.0.0:6379(aeMain+0x43) [0x55d17e4557f3]
keydb-rdb-bgsave 0.0.0.0:6379(workerThreadMain(void*)+0x6a) [0x55d17e45ce2a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4) [0x7fc423f194a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fc423c5bd0f]

------ INFO OUTPUT ------
# Server
redis_version:6.2.2
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:1d7b8f1c565b61df
redis_mode:standalone
os:Linux 5.15.35-1-pve x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:atomic-builtin
gcc_version:6.3.0
process_id:1440849
process_supervised:no
run_id:7542f137653d0fea39137fb6ea0056df3f6ed003
tcp_port:6379
server_time_usec:1655818811019543
uptime_in_seconds:70177
uptime_in_days:0
hz:20
configured_hz:10
lru_clock:11651643
executable:/usr/bin/keydb-server
config_file:/etc/keydb/keydb.conf

# Clients
connected_clients:3287
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:65568
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0
current_client_thread:0
thread_0_clients:852
thread_1_clients:271
thread_2_clients:271
thread_3_clients:271
thread_4_clients:271
thread_5_clients:271
thread_6_clients:270
thread_7_clients:270
thread_8_clients:270
thread_9_clients:270

# Memory
used_memory:13337587200
used_memory_human:12.42G
used_memory_rss:14800162816
used_memory_rss_human:13.78G
used_memory_peak:13612714000
used_memory_peak_human:12.68G
used_memory_peak_perc:97.98%
used_memory_overhead:1088825872
used_memory_startup:6475392
used_memory_dataset:12248761328
used_memory_dataset_perc:91.88%
allocator_allocated:13338233832
allocator_active:14920740864
allocator_resident:15152582656
total_system_memory:2151648985088
total_system_memory_human:1.96T
used_memory_lua:37888
used_memory_lua_human:37.00K
used_memory_scripts:0
used_memory_scripts_human:0B
number_of_cached_scripts:0
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:1.12
allocator_frag_bytes:1582507032
allocator_rss_ratio:1.02
allocator_rss_bytes:231841792
rss_overhead_ratio:0.98
rss_overhead_bytes:-352419840
mem_fragmentation_ratio:1.11
mem_fragmentation_bytes:1462577760
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:67425040
mem_aof_buffer:0
mem_allocator:jemalloc-5.2.1
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:584785
rdb_bgsave_in_progress:0
rdb_last_save_time:1655818750
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:85
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:450400256
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
module_fork_in_progress:0
module_fork_last_cow_size:0

# Stats
total_connections_received:696486
total_commands_processed:974414616
instantaneous_ops_per_sec:18758
total_net_input_bytes:432607020459
total_net_output_bytes:141632273139
instantaneous_input_kbps:10273.23
instantaneous_output_kbps:2734.54
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:822646
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:799627248
keyspace_misses:55433507
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:905443
total_forks:494
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
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:10904217
dump_payload_sanitizations:0
total_reads_processed:978383777
total_writes_processed:934890164

# Replication
role:master
connected_slaves:0
master_failover_state:no-failover
master_replid:d9e274aeccd6d1910a1c443bf8241fef1cb5def7
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:1.427848
used_cpu_user:0.598260
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000
server_threads:10
long_lock_waits:88858
used_cpu_sys_main_thread:1.427848
used_cpu_user_main_thread:0.598260

# Modules

# Commandstats
cmdstat_expire:calls=1645771,usec=22734534,usec_per_call=13.81,rejected_calls=0,failed_calls=0
cmdstat_object:calls=1,usec=2,usec_per_call=2.00,rejected_calls=0,failed_calls=0
cmdstat_hdel:calls=377229,usec=1109060,usec_per_call=2.94,rejected_calls=0,failed_calls=0
cmdstat_hmget:calls=3820762,usec=27225800,usec_per_call=7.13,rejected_calls=11730,failed_calls=0
cmdstat_smembers:calls=56475136,usec=200544869,usec_per_call=3.55,rejected_calls=5743,failed_calls=0
cmdstat_hset:calls=380904,usec=12280493,usec_per_call=32.24,rejected_calls=0,failed_calls=0
cmdstat_hscan:calls=1,usec=7,usec_per_call=7.00,rejected_calls=0,failed_calls=0
cmdstat_hget:calls=299935209,usec=1318497844,usec_per_call=4.40,rejected_calls=687381,failed_calls=0
cmdstat_type:calls=101,usec=206,usec_per_call=2.04,rejected_calls=0,failed_calls=0
cmdstat_command:calls=3,usec=4764,usec_per_call=1588.00,rejected_calls=0,failed_calls=0
cmdstat_set:calls=879089,usec=20004785,usec_per_call=22.76,rejected_calls=98,failed_calls=0
cmdstat_hlen:calls=2,usec=14,usec_per_call=7.00,rejected_calls=0,failed_calls=0
cmdstat_select:calls=10333,usec=13539,usec_per_call=1.31,rejected_calls=0,failed_calls=0
cmdstat_ping:calls=69823075,usec=21607132,usec_per_call=0.31,rejected_calls=0,failed_calls=0
cmdstat_hmset:calls=46194828,usec=821059038,usec_per_call=17.77,rejected_calls=9969678,failed_calls=0
cmdstat_get:calls=734242,usec=10442591,usec_per_call=14.22,rejected_calls=15,failed_calls=1
cmdstat_pttl:calls=1,usec=3,usec_per_call=3.00,rejected_calls=0,failed_calls=0
cmdstat_scan:calls=1,usec=1400,usec_per_call=1400.00,rejected_calls=0,failed_calls=0
cmdstat_info:calls=42626,usec=53404647,usec_per_call=1252.87,rejected_calls=0,failed_calls=0
cmdstat_hgetall:calls=494095300,usec=3568415806,usec_per_call=7.22,rejected_calls=229571,failed_calls=0
cmdstat_config:calls=2,usec=274,usec_per_call=137.00,rejected_calls=0,failed_calls=0

# Errorstats
errorstat_LOADING:count=10904216
errorstat_WRONGTYPE:count=1

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=14421156,expires=12415225,avg_ttl=1073765901
db6:keys=1542282,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------
1440849:1200209:C 21 Jun 2022 13:40:14.003 # Out Of Memory allocating 657410 bytes!
1440849:1200209:C 21 Jun 2022 13:40:14.003 # ------------------------------------------------
1440849:1200209:C 21 Jun 2022 13:40:14.003 # !!! Software Failure. Press left mouse button to continue
1440849:1200209:C 21 Jun 2022 13:40:14.003 # Guru Meditation: KeyDB aborting for OUT OF MEMORY. Allocating 657410 bytes! #server.cpp:6412

------ STACK TRACE ------

Backtrace:
keydb-rdb-bgsave 0.0.0.0:6379(redisOutOfMemoryHandler(unsigned long)+0x2a) [0x55d17e459eaa]
keydb-rdb-bgsave 0.0.0.0:6379(zmalloc_usable+0x2e) [0x55d17e46a46e]
keydb-rdb-bgsave 0.0.0.0:6379(_sdsnewlen+0x135) [0x55d17e466f35]
keydb-rdb-bgsave 0.0.0.0:6379(getAllClientsInfoString(int)+0x53) [0x55d17e477433]
keydb-rdb-bgsave 0.0.0.0:6379(logServerInfo()+0x4e) [0x55d17e4cc19e]
keydb-rdb-bgsave 0.0.0.0:6379(printCrashReport()+0x13) [0x55d17e4cc7f3]
keydb-rdb-bgsave 0.0.0.0:6379(_serverPanic+0xfb) [0x55d17e4ccaeb]
keydb-rdb-bgsave 0.0.0.0:6379(redisOutOfMemoryHandler(unsigned long)+0x2a) [0x55d17e459eaa]
keydb-rdb-bgsave 0.0.0.0:6379(zmalloc+0x2e) [0x55d17e46a41e]
keydb-rdb-bgsave 0.0.0.0:6379(+0x9ef39) [0x55d17e49ef39]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveRawString(_rio*, unsigned char const*, unsigned long)+0x54) [0x55d17e49f2c4]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveObject(_rio*, robj_roptr, redisObject*)+0x155) [0x55d17e4a0375]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveKeyValuePair(_rio*, redisObject*, redisObject*, expireEntry*)+0x104) [0x55d17e4a0f74]
keydb-rdb-bgsave 0.0.0.0:6379(saveKey(_rio*, redisDb*, int, unsigned long*, char const*, redisObject*)+0x7b) [0x55d17e4a137b]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveRio(_rio*, int*, int, rdbSaveInfo*)+0x23d) [0x55d17e4a176d]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveFile(char*, rdbSaveInfo*)+0xae) [0x55d17e4a24de]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSave(rdbSaveInfo*)+0x1f) [0x55d17e4a276f]
keydb-rdb-bgsave 0.0.0.0:6379(rdbSaveBackground(rdbSaveInfo*)+0xbf) [0x55d17e4a285f]
keydb-rdb-bgsave 0.0.0.0:6379(serverCron(aeEventLoop*, long long, void*)+0x6c4) [0x55d17e464ed4]
keydb-rdb-bgsave 0.0.0.0:6379(aeProcessEvents+0x33d) [0x55d17e45554d]
keydb-rdb-bgsave 0.0.0.0:6379(aeMain+0x43) [0x55d17e4557f3]
keydb-rdb-bgsave 0.0.0.0:6379(workerThreadMain(void*)+0x6a) [0x55d17e45ce2a]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x74a4) [0x7fc423f194a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fc423c5bd0f]
...

Additional information

https://github.com/Snapchat/KeyDB/issues/271

Hi @rnz we're on version 5.2.1 of jemalloc so the 271 fix should still be there.

Is the issue that memory usage is higher than before? Perhaps its related to #460 ?

Again this error on version 6.2.2 (when vm.max_map_count = 1048576): steps:

1. setup 5 new containers with debian 11
2. install keydb 6.2.2 on each
3. make multi-master configuration
4. when all hosts is negotiated - to one of nodes add replica from standalone keydb 6.0.18 with ~16mln keys.
5. wait some hours

...
3776007:3776212:S 14 Dec 2022 17:48:33.331 # Done loading RDB, keys loaded: 16584438, keys expired: 0.
3776007:3776212:S 14 Dec 2022 17:48:33.369 * MASTER <-> REPLICA sync: Finished with success
3776007:3776212:S 14 Dec 2022 17:48:33.478 # Connection with master lost.
3776007:3776212:S 14 Dec 2022 17:48:33.478 * Caching the disconnected master state.
3776007:3776212:S 14 Dec 2022 17:48:33.772 * Connecting to MASTER kdb14-prod:8379
3776007:3776212:S 14 Dec 2022 17:48:33.774 * MASTER <-> REPLICA sync started
3776007:3776212:S 14 Dec 2022 17:48:33.775 * Non blocking connect for SYNC fired the event.
3776007:3776212:S 14 Dec 2022 17:48:33.776 * Master replied to PING, replication can continue...
3776007:3776212:S 14 Dec 2022 17:48:33.778 * Partial resynchronization not possible (no cached master)
3776007:3776212:S 14 Dec 2022 17:48:34.046 # Connection with master lost.
3776007:3776212:S 14 Dec 2022 17:48:34.046 * Caching the disconnected master state.
3776007:3776212:S 14 Dec 2022 17:48:34.277 * Full resync from master: 354dc73ae969a6090c5007bfcf722407e9f38b94:318919654684
3776007:3776212:S 14 Dec 2022 17:48:34.277 * Discarding previously cached master state.
3776007:3776212:S 14 Dec 2022 17:48:59.372 * Synchronization with replica 10.100.15.156:8379 succeeded
3776007:3776212:S 14 Dec 2022 17:49:06.373 * Synchronization with replica 10.101.231.210:8379 succeeded
3776007:3776212:S 14 Dec 2022 17:49:06.887 * Synchronization with replica 10.101.73.176:8379 succeeded
3776007:3776212:S 14 Dec 2022 17:49:07.105 * Synchronization with replica 10.102.176.69:8379 succeeded
3776007:3776212:S 14 Dec 2022 17:49:26.099 * 50000 changes in 300 seconds. Saving...
3776007:3776212:S 14 Dec 2022 17:49:27.246 * Background saving started by pid 3790314
3776007:3776212:S 14 Dec 2022 17:50:20.309 # Connection with master lost.
3776007:3776212:S 14 Dec 2022 17:50:20.309 * Caching the disconnected master state.
3776007:3776212:S 14 Dec 2022 17:50:20.311 # Connection with replica client id #7082 lost.
3790314:3776212:C 14 Dec 2022 17:50:23.696 * DB saved on disk
3790314:3776212:C 14 Dec 2022 17:50:25.378 * RDB: 6624 MB of memory used by copy-on-write
3776007:3776212:S 14 Dec 2022 17:50:27.186 * Background saving terminated with success
3776007:3776212:S 14 Dec 2022 17:50:56.909 * Replica 10.101.231.210:8379 asks for synchronization
3776007:3776212:S 14 Dec 2022 17:50:56.909 * Full resync requested by replica 10.101.231.210:8379
3776007:3776212:S 14 Dec 2022 17:50:56.909 * Starting BGSAVE for SYNC with target: disk
3776007:3776212:S 14 Dec 2022 17:50:58.436 * Background saving started by pid 3790799
3790799:3776212:C 14 Dec 2022 17:51:26.022 # Out Of Memory allocating 4002 bytes!
3790799:3776212:C 14 Dec 2022 17:51:26.022 # ------------------------------------------------
3790799:3776212:C 14 Dec 2022 17:51:26.022 # !!! Software Failure. Press left mouse button to continue
3790799:3776212:C 14 Dec 2022 17:51:26.022 # Guru Meditation: KeyDB aborting for OUT OF MEMORY. Allocating 4002 bytes! #server.cpp:6411
3790799:3776212:C 14 Dec 2022 17:51:26.025 # Out Of Memory allocating 10246 bytes!
3790799:3776212:C 14 Dec 2022 17:51:26.025 # ------------------------------------------------
3790799:3776212:C 14 Dec 2022 17:51:26.025 # !!! Software Failure. Press left mouse button to continue
3790799:3776212:C 14 Dec 2022 17:51:26.025 # Guru Meditation: KeyDB aborting for OUT OF MEMORY. Allocating 10246 bytes! #server.cpp:6411
3790799:3776212:C 14 Dec 2022 17:51:26.028 # Out Of Memory allocating 10246 bytes!
3790799:3776212:C 14 Dec 2022 17:51:26.028 # ------------------------------------------------
...

Hi, as discussed in another issue this is not a supported configuration, going to close this issue.