Memory leak and confusing logs

[yatriks]

Hi all,

I've been really enjoying my use of kvrocks so far, and everyone has done a fantastic job on it.

I'm running into some issues now that my database is in the ~100s of GBs. I'm using the default kvrocks.conf except I have the repl-namespace-enabled set to yes, because I set it to that when I was testing maybe having a read replica.
(I am running the 2.12.1).

1. It seemed like the container would run out of memory (and not quite like this Memory Leak in KVROCKS？ #2784 where the reported memory in kvrocks is different from the memory visible to the OS) seemingly randomly, though looking at my prometheus stats it seems like a compaction is pending right before the memory starts to rise. I have the docker container limit at 12GB, but it always agrees (very closely...) with the kvrocks reported memory. And in any case, the MALLOC changes in that thread didn't make a difference)

This is hard to describe, so please let me know what information I can get that helps (I am also trying to recreate this in a self-contained docker compose file with the default container, but haven't been able to yet -- which means maybe I'm doing something wrong in my setup...). I've attached a screenshot of seemingly relevant metrics from kvrocks-exporter but I can get whatever other information.

This last one is taken during the period of the memory spike.

2. The only logs I see lately are:

kv-1  | E20250520 06:16:23.964952 140052344587968 compaction_checker.cc:88] [compaction checker] Parse total_keys error: out of range of integer type

That hasn't happened since I restarted the container recently, but it was consistent before (though it didn't seem to affect anything...)

Again, it's a lot of weirdness, so please let me know what other information I can get. I'm trying to reliably reproduce it but when I saw that it had just spiked when I wasn't testing anything at all, I think I need some help.

Thanks again.

[git-hulk]

@yatriks Could you please provide the result of the command: config get * and info via the redis-cli.

[yatriks]

Of course 👍 thanks!

127.0.0.1:6666> info
# Server
version:2.12.1
kvrocks_version:2.12.1
redis_version:4.0.0
git_sha1:06e24fa0
kvrocks_git_sha1:06e24fa0
redis_mode:standalone
kvrocks_mode:standalone
os:Linux 5.14.0-427.16.1.el9_4.x86_64 x86_64
clang_version:14.0.6
rocksdb_version:10.1.0
arch_bits:64
process_id:8
tcp_port:6666
server_time_usec:1747838500590979
uptime_in_seconds:66288
uptime_in_days:0
executable:/usr/bin/kvrocks
config_file:/var/lib/kvconf/kvrocks.conf

# Clients
maxclients:10000
connected_clients:5
monitor_clients:0
blocked_clients:0

# Memory
used_memory_rss:5920350208
used_memory_rss_human:5.51G
used_memory_lua:319488
used_memory_lua_human:312.00K
used_memory_startup:224366592

# Persistence
loading:0
bgsave_in_progress:0
last_bgsave_time:1747772212
last_bgsave_status:ok
last_bgsave_time_sec:-1

# Stats
total_connections_received:3210
total_commands_processed:311798535
instantaneous_ops_per_sec:2932
total_net_input_bytes:26845056782
total_net_output_bytes:30502466557
instantaneous_input_kbps:0.000000
instantaneous_output_kbps:11.000000
sync_full:0
sync_partial_ok:0
sync_partial_err:0
keyspace_hits:332394262
keyspace_misses:87709
pubsub_channels:0
pubsub_patterns:0

# Replication
role:master
connected_slaves:0
master_repl_offset:18859871023

# CPU
used_cpu_sys:30083.000000
used_cpu_user:147594.000000

# CommandStats
cmdstat_auth:calls=3210,usec=6619,usec_per_call=2.061993769470405
cmdstat_client:calls=1105,usec=268,usec_per_call=0.2425339366515837
cmdstat_command:calls=2,usec=4050,usec_per_call=2025
cmdstat_config:calls=1105,usec=80472,usec_per_call=72.82533936651583
cmdstat_dbsize:calls=1,usec=6,usec_per_call=6
cmdstat_exec:calls=20633,usec=59996532113,usec_per_call=2907794.8971550427
cmdstat_hset:calls=3094818,usec=144075839,usec_per_call=46.55389719201582
cmdstat_info:calls=1107,usec=2097992,usec_per_call=1895.205058717254
cmdstat_multi:calls=20633,usec=2769,usec_per_call=0.13420249115494595
cmdstat_ping:calls=3189,usec=181,usec_per_call=0.05675760426465977
cmdstat_select:calls=4,usec=1,usec_per_call=0.25
cmdstat_slowlog:calls=2210,usec=4563,usec_per_call=2.0647058823529414
cmdstat_unlink:calls=5158,usec=540279,usec_per_call=104.74583171772005
cmdstat_zadd:calls=103165000,usec=24309634311,usec_per_call=235.63838812581787
cmdstat_zrange:calls=5159,usec=47191332,usec_per_call=9147.379724752858
cmdstat_zrem:calls=203589820,usec=34385612696,usec_per_call=168.89652290080122
cmdstat_zunion:calls=1885381,usec=4434494541,usec_per_call=2352.0415984885813

# Cluster
cluster_enabled:0

# Keyspace
last_dbsize_scan_timestamp:0
db0:keys=0,expires=0,avg_ttl=0,expired=0
sequence:18859871023
used_db_size:262220453761
max_db_size:0
used_percent:0%
disk_capacity:527294529536
used_disk_size:335423287296
used_disk_percent:63.61213107808273%

# RocksDB
block_cache_usage:4293947840
block_cache_pinned_usage[default]:257736160
estimate_keys[default]:5672763954
index_and_filter_cache_usage[default]:1392495
level0_file_limit_slowdown[default]:0
level0_file_limit_stop[default]:0
pending_compaction_bytes_slowdown[default]:0
pending_compaction_bytes_stop[default]:0
level0_file_limit_stop_with_ongoing_compaction[default]:0
level0_file_limit_slowdown_with_ongoing_compaction[default]:0
memtable_count_limit_slowdown[default]:0
memtable_count_limit_stop[default]:0
estimate_keys[metadata]:192537584
index_and_filter_cache_usage[metadata]:51833
level0_file_limit_slowdown[metadata]:0
level0_file_limit_stop[metadata]:0
pending_compaction_bytes_slowdown[metadata]:0
pending_compaction_bytes_stop[metadata]:0
level0_file_limit_stop_with_ongoing_compaction[metadata]:0
level0_file_limit_slowdown_with_ongoing_compaction[metadata]:0
memtable_count_limit_slowdown[metadata]:3
memtable_count_limit_stop[metadata]:0
estimate_keys[zset_score]:5285706406
index_and_filter_cache_usage[zset_score]:118225110
level0_file_limit_slowdown[zset_score]:0
level0_file_limit_stop[zset_score]:0
pending_compaction_bytes_slowdown[zset_score]:0
pending_compaction_bytes_stop[zset_score]:0
level0_file_limit_stop_with_ongoing_compaction[zset_score]:0
level0_file_limit_slowdown_with_ongoing_compaction[zset_score]:0
memtable_count_limit_slowdown[zset_score]:0
memtable_count_limit_stop[zset_score]:0
estimate_keys[pubsub]:0
index_and_filter_cache_usage[pubsub]:0
level0_file_limit_slowdown[pubsub]:0
level0_file_limit_stop[pubsub]:0
pending_compaction_bytes_slowdown[pubsub]:0
pending_compaction_bytes_stop[pubsub]:0
level0_file_limit_stop_with_ongoing_compaction[pubsub]:0
level0_file_limit_slowdown_with_ongoing_compaction[pubsub]:0
memtable_count_limit_slowdown[pubsub]:0
memtable_count_limit_stop[pubsub]:0
estimate_keys[propagate]:1
index_and_filter_cache_usage[propagate]:2646
level0_file_limit_slowdown[propagate]:0
level0_file_limit_stop[propagate]:0
pending_compaction_bytes_slowdown[propagate]:0
pending_compaction_bytes_stop[propagate]:0
level0_file_limit_stop_with_ongoing_compaction[propagate]:0
level0_file_limit_slowdown_with_ongoing_compaction[propagate]:0
memtable_count_limit_slowdown[propagate]:0
memtable_count_limit_stop[propagate]:0
estimate_keys[stream]:0
index_and_filter_cache_usage[stream]:0
level0_file_limit_slowdown[stream]:0
level0_file_limit_stop[stream]:0
pending_compaction_bytes_slowdown[stream]:0
pending_compaction_bytes_stop[stream]:0
level0_file_limit_stop_with_ongoing_compaction[stream]:0
level0_file_limit_slowdown_with_ongoing_compaction[stream]:0
memtable_count_limit_slowdown[stream]:0
memtable_count_limit_stop[stream]:0
estimate_keys[search]:0
index_and_filter_cache_usage[search]:0
level0_file_limit_slowdown[search]:0
level0_file_limit_stop[search]:0
pending_compaction_bytes_slowdown[search]:0
pending_compaction_bytes_stop[search]:0
level0_file_limit_stop_with_ongoing_compaction[search]:0
level0_file_limit_slowdown_with_ongoing_compaction[search]:0
memtable_count_limit_slowdown[search]:0
memtable_count_limit_stop[search]:0
block_cache_data_hit:5390364628
block_cache_data_miss:669881405
block_cache_filter_hit:9305895281
block_cache_filter_miss:171282235
block_cache_hit:19601813276
block_cache_index_hit:4905553367
block_cache_index_miss:257301191
block_cache_miss:1098464831
all_mem_tables:117454848
cur_mem_tables:117454848
snapshots:0
num_immutable_tables:0
num_running_flushes:0
memtable_flush_pending:0
compaction_pending:2
num_running_compactions:3
num_live_versions:9
num_super_version:3431
num_background_errors:0
flush_count:480
compaction_count:1985
put_per_sec:9375
get_per_sec:75797
seek_per_sec:0
next_per_sec:0
prev_per_sec:0
is_bgsaving:no
is_compacting:no
(1.17s)

and

127.0.0.1:6666> config get *
  1) "auto-resize-block-and-sst"
  2) "yes"
  3) "backup-dir"
  4) "/var/lib/kvrocks/backup"
  5) "bgsave-cron"
  6) ""
  7) "bind"
  8) "0.0.0.0"
  9) "cluster-enabled"
 10) "no"
 11) "compact-cron"
 12) "0 10-11 * * *"
 13) "compaction-checker-cron"
 14) "* 10-11 * * *"
 15) "compaction-checker-range"
 16) ""
 17) "daemonize"
 18) "no"
 19) "db-name"
 20) "change.me.db"
 21) "dbsize-scan-cron"
 22) ""
 23) "dir"
 24) "/var/lib/kvrocks"
 25) "force-compact-file-age"
 26) "172800"
 27) "force-compact-file-min-deleted-percentage"
 28) "10"
 29) "fullsync-recv-file-delay"
 30) "0"
 31) "histogram-bucket-boundaries"
 32) ""
 33) "json-max-nesting-depth"
 34) "1024"
 35) "json-storage-format"
 36) "json"
 37) "log-dir"
 38) "/var/lib/kvrocks"
 39) "log-level"
 40) "info"
 41) "log-retention-days"
 42) "-1"
 43) "master-use-repl-port"
 44) "no"
 45) "masterauth"
 46) ""
 47) "max-backup-keep-hours"
 48) "24"
 49) "max-backup-to-keep"
 50) "1"
 51) "max-bitmap-to-string-mb"
 52) "16"
 53) "max-db-size"
 54) "0"
 55) "max-io-mb"
 56) "0"
 57) "max-replication-mb"
 58) "0"
 59) "maxclients"
 60) "10000"
 61) "migrate-batch-rate-limit-mb"
 62) "16"
 63) "migrate-batch-size-kb"
 64) "16"
 65) "migrate-pipeline-size"
 66) "16"
 67) "migrate-sequence-gap"
 68) "10000"
 69) "migrate-speed"
 70) "4096"
 71) "migrate-type"
 72) "redis-command"
 73) "persist-cluster-nodes-enabled"
 74) "yes"
 75) "pidfile"
 76) "/var/run/kvrocks/kvrocks.pid"
 77) "port"
 78) "6666"
 79) "profiling-sample-commands"
 80) ""
 81) "profiling-sample-ratio"
 82) "0"
 83) "profiling-sample-record-max-len"
 84) "256"
 85) "profiling-sample-record-threshold-ms"
 86) "100"
 87) "proto-max-bulk-len"
 88) "536870912"
 89) "purge-backup-on-fullsync"
 90) "no"
 91) "redis-cursor-compatible"
 92) "yes"
 93) "repl-namespace-enabled"
 94) "yes"
 95) "replica-announce-ip"
 96) ""
 97) "replica-announce-port"
 98) "0"
 99) "replicaof"
100) ""
101) "replication-connect-timeout-ms"
102) "3100"
103) "replication-recv-timeout-ms"
104) "3200"
105) "requirepass"
106) "test"
107) "resp3-enabled"
108) "yes"
109) "rocksdb.avoid_unnecessary_blocking_io"
110) "yes"
111) "rocksdb.blob_file_size"
112) "268435456"
113) "rocksdb.blob_garbage_collection_age_cutoff"
114) "25"
115) "rocksdb.block_cache_size"
116) "4096"
117) "rocksdb.block_cache_type"
118) "lru"
119) "rocksdb.block_size"
120) "16384"
121) "rocksdb.cache_index_and_filter_blocks"
122) "yes"
123) "rocksdb.compaction_readahead_size"
124) "2097152"
125) "rocksdb.compression"
126) "snappy"
127) "rocksdb.compression_level"
128) "32767"
129) "rocksdb.compression_start_level"
130) "2"
131) "rocksdb.delayed_write_rate"
132) "0"
133) "rocksdb.disable_auto_compactions"
134) "no"
135) "rocksdb.dump_malloc_stats"
136) "yes"
137) "rocksdb.enable_blob_files"
138) "no"
139) "rocksdb.enable_blob_garbage_collection"
140) "yes"
141) "rocksdb.enable_pipelined_write"
142) "no"
143) "rocksdb.level0_file_num_compaction_trigger"
144) "4"
145) "rocksdb.level0_slowdown_writes_trigger"
146) "20"
147) "rocksdb.level0_stop_writes_trigger"
148) "40"
149) "rocksdb.level_compaction_dynamic_level_bytes"
150) "yes"
151) "rocksdb.max_background_compactions"
152) "-1"
153) "rocksdb.max_background_flushes"
154) "-1"
155) "rocksdb.max_background_jobs"
156) "4"
157) "rocksdb.max_bytes_for_level_base"
158) "268435456"
159) "rocksdb.max_bytes_for_level_multiplier"
160) "10"
161) "rocksdb.max_compaction_bytes"
162) "0"
163) "rocksdb.max_open_files"
164) "8096"
165) "rocksdb.max_subcompactions"
166) "2"
167) "rocksdb.max_total_wal_size"
168) "512"
169) "rocksdb.max_write_buffer_number"
170) "4"
171) "rocksdb.metadata_block_cache_size"
172) "2048"
173) "rocksdb.min_blob_size"
174) "4096"
175) "rocksdb.partition_filters"
176) "yes"
177) "rocksdb.rate_limiter_auto_tuned"
178) "yes"
179) "rocksdb.read_options.async_io"
180) "yes"
181) "rocksdb.row_cache_size"
182) "0"
183) "rocksdb.share_metadata_and_subkey_block_cache"
184) "yes"
185) "rocksdb.stats_dump_period_sec"
186) "0"
187) "rocksdb.subkey_block_cache_size"
188) "2048"
189) "rocksdb.target_file_size_base"
190) "128"
191) "rocksdb.wal_compression"
192) "no"
193) "rocksdb.wal_size_limit_mb"
194) "16384"
195) "rocksdb.wal_ttl_seconds"
196) "10800"
197) "rocksdb.write_buffer_size"
198) "64"
199) "rocksdb.write_options.disable_wal"
200) "no"
201) "rocksdb.write_options.low_pri"
202) "no"
203) "rocksdb.write_options.memtable_insert_hint_per_batch"
204) "no"
205) "rocksdb.write_options.no_slowdown"
206) "no"
207) "rocksdb.write_options.sync"
208) "no"
209) "rocksdb.write_options.write_batch_max_bytes"
210) "0"
211) "skip-block-cache-deallocation-on-close"
212) "no"
213) "slave-empty-db-before-fullsync"
214) "no"
215) "slave-priority"
216) "100"
217) "slave-read-only"
218) "yes"
219) "slave-serve-stale-data"
220) "yes"
221) "slaveof"
222) ""
223) "slowlog-log-slower-than"
224) "100000"
225) "slowlog-max-len"
226) "128"
227) "socket-fd"
228) "-1"
229) "supervised"
230) "no"
231) "tcp-backlog"
232) "511"
233) "timeout"
234) "0"
235) "tls-auth-clients"
236) ""
237) "tls-ca-cert-dir"
238) ""
239) "tls-ca-cert-file"
240) ""
241) "tls-cert-file"
242) ""
243) "tls-ciphers"
244) ""
245) "tls-ciphersuites"
246) ""
247) "tls-key-file"
248) ""
249) "tls-key-file-pass"
250) ""
251) "tls-port"
252) "0"
253) "tls-prefer-server-ciphers"
254) "no"
255) "tls-protocols"
256) ""
257) "tls-replication"
258) "no"
259) "tls-session-cache-size"
260) "20480"
261) "tls-session-cache-timeout"
262) "300"
263) "tls-session-caching"
264) "yes"
265) "txn-context-enabled"
266) "no"
267) "unixsocket"
268) ""
269) "unixsocketperm"
270) "777"
271) "use-rsid-psync"
272) "no"
273) "workers"
274) "8"
(6.55s)

[yatriks]

@git-hulk Thanks, I have set up the new nightly build and am profiling it now, with stats collecting correctly. I will report back.

[git-hulk]

@yatriks Great, thanks for your prompt update.

[yatriks]

@git-hulk
Ok, I've been running this with the profiling for a couple of days and of course (as is often the case when debugging...) it has been perfectly fine.

I changed the memory limit to 7GiB. Now there's the strange behaviour where I do see info report used rss memory to be greater than 7GiB, and this happens few times a day. However, docker stats always sees a number below 7GiB, and the container has yet to be oom killed. I am collecting some more detailed stats about this behaviour now, and will create the same dumps/visualizations as before.

I have jeprof heap dumps from when the memory exceeds 7GiB, but I don't understand how to use them (yet). I have attached one here, let me know what else I can do or what you think may be happening.

jeprof.8.2699.i2699.heap.txt

[git-hulk]

It requires the program binary to inspect the heap profiling. You can use jeprof --base to view the memory allocations between two heaps, refer to: https://manpages.debian.org/unstable/libjemalloc-dev/jeprof.1.en.html.

After PR #3007 and #3011, we can dump the heap manually at runtime:

## Enable the memory profiling, set prof_active to true.
$ redis-cli> KPROFILE MEMORY ENABLE

## Inspect the profiling status
$ redis-cli> KPROFILE MEMORY status

## Dump the profiling file into /tmp directory, which named with `jeprof_` prefix.
$ redis-cli> KPROFILE MEMORY DUMP /tmp

## Disable the memory profiling, set prof_active to false.
$ redis-cli> KPROFILE MEMORY DISABLE

[yatriks]

Just to follow up...I've observed a lot and I haven't had another oom-related issue on kvrocks since the profiling tools...I'm not sure about causality, but I am satisfied with the addition of these tools being the resolution to this discussion. I find them very helpful, and if I run into this issue again, I can use them to make a detailed report.

Thanks again for all your help, our usage of kvrocks is inching closer and closer to production.