Redisearch: [MAJOR] 1.99.2 memory consumption off the charts

[kkmuffme]

With redisearch 1.99.2 (M2) there seems to be an issue with memory consumption of redis master:

• there are 0 keys in redis
• there are redis indexes created
• only using aof (dump.rdb only for initial sync of slaves)
  85M appendonly.aof
  108K dump.rdb
• redis master uses 5GB (= maxmemory value, otherwise would even use more), causing OOM errors
• redis slaves use less than 1GB
• Issue happens every few days.
• I fixed the issue by deleting the aof/rdb files & restarting redis master, but that's not a permanent solution (since all redis data is lost)
• we didn't have this issue on 1.99.1 (though it may have been lucky, as we didn't use it for too long, but I think it's new in 1.99.1)
• we don't have this issue with RediSearch 1.6.13 (on Redis 6 too) on a master/slave setup with identical redis.conf files.

redis master info memory

redis-cli -h 127.0.0.1 -p 6379 -a foobar keys '*'
Warning: Using a password with '-a' or '-u' option on the command line interface may not be safe.
(empty array)

redis-cli -h 127.0.0.1 -p 6379 -a foobar info memory
Warning: Using a password with '-a' or '-u' option on the command line interface may not be safe.
# Memory
used_memory:5372102192
used_memory_human:5.00G
used_memory_rss:5330169856
used_memory_rss_human:4.96G
used_memory_peak:5373977752
used_memory_peak_human:5.00G
used_memory_peak_perc:99.97%
used_memory_overhead:537737404
used_memory_startup:831560
used_memory_dataset:4834364788
used_memory_dataset_perc:90.00%
allocator_allocated:5372381928
allocator_active:5450297344
allocator_resident:5535256576
total_system_memory:32933359616
total_system_memory_human:30.67G
used_memory_lua:43008
used_memory_lua_human:42.00K
used_memory_scripts:960
used_memory_scripts_human:960B
number_of_cached_scripts:4
maxmemory:5368709120
maxmemory_human:5.00G
maxmemory_policy:allkeys-lru
allocator_frag_ratio:1.01
allocator_frag_bytes:77915416
allocator_rss_ratio:1.02
allocator_rss_bytes:84959232
rss_overhead_ratio:0.96
rss_overhead_bytes:-205086720
mem_fragmentation_ratio:0.99
mem_fragmentation_bytes:-41870312
mem_not_counted_for_evict:0
mem_replication_backlog:536870912
mem_clients_slaves:33972
mem_clients_normal:0
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

When checking on the slave:

redis slave info memory

redis-cli -s /var/run/redis2/redis2.sock info memory
# Memory
used_memory:865816736
used_memory_human:825.71M
used_memory_rss:1267683328
used_memory_rss_human:1.18G
used_memory_peak:4949439792
used_memory_peak_human:4.61G
used_memory_peak_perc:17.49%
used_memory_overhead:2525334
used_memory_startup:831288
used_memory_dataset:863291402
used_memory_dataset_perc:99.80%
allocator_allocated:866645256
allocator_active:1182322688
allocator_resident:1299005440
total_system_memory:32933359616
total_system_memory_human:30.67G
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.36
allocator_frag_bytes:315677432
allocator_rss_ratio:1.10
allocator_rss_bytes:116682752
rss_overhead_ratio:0.98
rss_overhead_bytes:-31322112
mem_fragmentation_ratio:1.46
mem_fragmentation_bytes:401928560
mem_not_counted_for_evict:0
mem_replication_backlog:1048576
mem_clients_slaves:0
mem_clients_normal:645470
mem_aof_buffer:0
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

[MeirShpilraien]

@kkmuffme thanks for reporting. Is it happened right after loading the aof (or over time)? If it happened right after loading the aof, is possible to share the aof with us in some way?

[MeirShpilraien]

@kkmuffme can you check again with the third milestone and let us know if it got better?

[kkmuffme]

@kkmuffme no it happens over time unfortunately.

Will test it with M3, but it will take 2-3 days again (as this is how long it usually took until the issue happened), and update here again then.

[MeirShpilraien]

@kkmuffme any updates?

[kkmuffme]

Sorry, for the late update but it seemed to be working now - at first at least.
After 6 days however, suddenly got read errors and redis was unresponsive (which is why I couldnt get any memory information either since no commands were working) - the out of memory issue is fixed now though.
Now however, the issue is that something makes redis unresponsive to all queries.
Again I had to delete the aof & rdb files, then restart redis, as restarting wasn't possible otherwise.

Waiting for a few days again to see if the issue reoccurs.

[MeirShpilraien]

@kkmuffme can you give us the oaf & rdb files to reproduce the issue and solve it?

[MeirShpilraien]

If you already deleted it, can you share with us the redis log file?

[kkmuffme]

I extracted the point in time where it started:

At 09:37 things work fine, at 22:03 it re-replicates a slave which leads to the master becoming unresponsive.
3 minutes later redis master is restarted by monit, since it has become unresponsive on 127.0.0.1:6379

2648552:M 24 Aug 2020 09:37:59.665 * <module> Scanning indexes in background: done (scanned=105)
2648552:M 24 Aug 2020 22:03:56.590 # Connection with replica 127.0.0.1:<unknown-replica-port> lost.
2648552:M 24 Aug 2020 22:03:58.935 * Replica 127.0.0.1:<unknown-replica-port> asks for synchronization
2648552:M 24 Aug 2020 22:03:59.193 * Partial resynchronization request from 127.0.0.1:<unknown-replica-port> accepted. Sending 73640678 bytes of backlog starting from offset 1.
2850595:C 24 Aug 2020 22:06:15.305 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo

This then goes on for almost 2 days, cycles of redis being restarted and restarted again (bc all devs where off due to holidays, who would normally monitor the dev server, where we have this issue) either by monit (when it had 3105908:signal-handler (1598397480) Received shutdown signal during loading, exiting now. or apparently by itself if it just puts redis is starting in the logs)
Essentially this again and again:

3086420:C 25 Aug 2020 20:56:43.263 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
3086420:C 25 Aug 2020 20:56:43.263 # Redis version=6.0.6, bits=64, commit=00000000, modified=0, pid=3086420, just started
3086420:C 25 Aug 2020 20:56:43.263 # Configuration loaded
3086420:C 25 Aug 2020 20:56:43.263 # WARNING supervised by systemd - you MUST set appropriate values for TimeoutStartSec and TimeoutStopSec in your service unit.
3086420:M 25 Aug 2020 20:56:43.265 * Running mode=standalone, port=6379.
3086420:M 25 Aug 2020 20:56:43.266 # Server initialized
3086420:M 25 Aug 2020 20:56:43.267 * <ft> RediSearch version 1.99.3 (Git=v1.99.2-11-g525eda2c)
3086420:M 25 Aug 2020 20:56:43.267 * <ft> Low level api version 1 initialized successfully
3086420:M 25 Aug 2020 20:56:43.267 * <ft> concurrent writes: OFF, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 500, timeout policy: return,
cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, max number of search results:  1000000, search pool size: 20, index pool size: 8,
3086420:M 25 Aug 2020 20:56:43.268 * <ft> Initialized thread pool!
3086420:M 25 Aug 2020 20:56:43.268 * Module 'ft' loaded from /usr/local/lib/redisearch.so
3086420:M 25 Aug 2020 20:56:43.269 * Reading RDB preamble from AOF file...
3086420:M 25 Aug 2020 20:56:43.269 * Loading RDB produced by version 6.0.6
3086420:M 25 Aug 2020 20:56:43.269 * RDB age 245117 seconds
3086420:M 25 Aug 2020 20:56:43.269 * RDB memory usage when created 5109.62 Mb
3086420:M 25 Aug 2020 20:56:43.269 * RDB has an AOF tail
3086420:M 25 Aug 2020 20:56:43.402 * Reading the remaining AOF tail...
3086754:C 25 Aug 2020 20:58:16.413 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
3086754:C 25 Aug 2020 20:58:16.413 # Redis version=6.0.6, bits=64, commit=00000000, modified=0, pid=3086754, just started
3086754:C 25 Aug 2020 20:58:16.413 # Configuration loaded
3086754:C 25 Aug 2020 20:58:16.413 # WARNING supervised by systemd - you MUST set appropriate values for TimeoutStartSec and TimeoutStopSec in your service unit.
3086754:M 25 Aug 2020 20:58:16.415 * Running mode=standalone, port=6379.
3086754:M 25 Aug 2020 20:58:16.415 # Server initialized
3086754:M 25 Aug 2020 20:58:16.417 * <ft> RediSearch version 1.99.3 (Git=v1.99.2-11-g525eda2c)
3086754:M 25 Aug 2020 20:58:16.417 * <ft> Low level api version 1 initialized successfully
3086754:M 25 Aug 2020 20:58:16.417 * <ft> concurrent writes: OFF, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 500, timeout policy: return,
cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, max number of search results:  1000000, search pool size: 20, index pool size: 8,
3086754:M 25 Aug 2020 20:58:16.417 * <ft> Initialized thread pool!
3086754:M 25 Aug 2020 20:58:16.417 * Module 'ft' loaded from /usr/local/lib/redisearch.so
3086754:M 25 Aug 2020 20:58:16.418 * Reading RDB preamble from AOF file...
3086754:M 25 Aug 2020 20:58:16.418 * Loading RDB produced by version 6.0.6
3086754:M 25 Aug 2020 20:58:16.418 * RDB age 245210 seconds
3086754:M 25 Aug 2020 20:58:16.418 * RDB memory usage when created 5109.62 Mb
3086754:M 25 Aug 2020 20:58:16.418 * RDB has an AOF tail
3086754:M 25 Aug 2020 20:58:16.542 * Reading the remaining AOF tail...

I will monitor it again now for the next days and see if this issue happens again, and send you the aof file & rdb file then.

[kkmuffme]

@MeirShpilraien unfortunately OOM errors are back now (on 1.99.3).
Config like before (initial post, 1.99.2), 0 keys (redis-cli keys '*' returns empty array) only contains redisearch indexes/data
Redis was flushed completely (incl. aof, rdb) + restarted 2 days ago.

aof & rdb file (= with this we had the oom errors): https://www.dropbox.com/s/7iq8vwfdjczo8ts/redis.zip?dl=0
Fyi we have only aof enabled, the rdb is just data that redis used to init the sync of the slaves. If you want to test/restore it, please use the aof file.

redis.log of today: https://www.dropbox.com/s/shl5v8xdiqdbwgw/redis.log?dl=0
The OOM errors started to happen at ~7:28am

About 30 minutes redis RAM usage started to increase by 1GB (from 4->5) - this coincides with the start of "Scanning index" at 06:59 you can see in the redis.log

The slaves are also very close to the memory limit now (around 4.7GB) too

# Memory
used_memory:5368713080
used_memory_human:5.00G
used_memory_rss:5601763328
used_memory_rss_human:5.22G
used_memory_peak:5369117520
used_memory_peak_human:5.00G
used_memory_peak_perc:99.99%
used_memory_overhead:537742712
used_memory_startup:831560
used_memory_dataset:4830970368
used_memory_dataset_perc:90.00%
allocator_allocated:5369256344
allocator_active:5525176320
allocator_resident:5608583168
total_system_memory:32933359616
total_system_memory_human:30.67G
used_memory_lua:8371200
used_memory_lua_human:7.98M
used_memory_scripts:2544
used_memory_scripts_human:2.48K
number_of_cached_scripts:10
maxmemory:5368709120
maxmemory_human:5.00G
maxmemory_policy:allkeys-lru
allocator_frag_ratio:1.03
allocator_frag_bytes:155919976
allocator_rss_ratio:1.02
allocator_rss_bytes:83406848
rss_overhead_ratio:1.00
rss_overhead_bytes:-6819840
mem_fragmentation_ratio:1.04
mem_fragmentation_bytes:233112256
mem_not_counted_for_evict:3724
mem_replication_backlog:536870912
mem_clients_slaves:33972
mem_clients_normal:0
mem_aof_buffer:3724
mem_allocator:jemalloc-5.1.0
active_defrag_running:0
lazyfree_pending_objects:0

[MeirShpilraien]

@kkmuffme I loaded your AOF file and it's loaded just fine after 247.554 seconds:

13387:M 30 Aug 2020 18:37:28.116 * <ft> Initialized thread pool!
13387:M 30 Aug 2020 18:37:28.116 * Module 'ft' loaded from ./build/redisearch.so
13387:M 30 Aug 2020 18:37:28.117 * Reading RDB preamble from AOF file...
13387:M 30 Aug 2020 18:37:28.117 * Loading RDB produced by version 6.0.6
13387:M 30 Aug 2020 18:37:28.117 * RDB age 227229 seconds
13387:M 30 Aug 2020 18:37:28.117 * RDB memory usage when created 3947.00 Mb
13387:M 30 Aug 2020 18:37:28.117 * RDB has an AOF tail
13387:M 30 Aug 2020 18:37:28.389 # RDB file was saved with checksum disabled: no check performed.
13387:M 30 Aug 2020 18:37:28.389 * Reading the remaining AOF tail...
13387:M 30 Aug 2020 18:41:35.670 * <module> Scanning all indexes
13387:M 30 Aug 2020 18:41:35.670 * DB loaded from append only file: 247.554 seconds
13387:M 30 Aug 2020 18:41:35.670 * Ready to accept connections

I believe you said your timeout is 3 minutes and here it took 3.7221 minutes, I believe you need to increase your timeout?

Regarding the high memory usage, from analyzing the AOF I see you use UNLINK command, which led me to understand that we did not register to UNLINK notification and did not delete the document from the index (and this is why we see high memory usage, the documents are still presenting in the index), thank you for finding it and we will fix it for the next milestone (or GA).

Regarding why the Redis got unresponsive from the first place, I am still not sure. I kind of suspect this issue: https://github.com/RediSearch/RediSearch/pull/1470 but I am gone need your help to prove it (or maybe prove that it's not this). Can you do a small script that extracts 'FT.INFO' from all documents each hour (until it will get unresponsive again)? I believe that by analyzing this and see the insertion pattern (amount of documents) over time we will be able to prove if its this or not. If it's not this maybe it will also give us another clew.

[kkmuffme]

@MeirShpilraien thanks for figuring this out, I will wait for 1.99.4 and test again.

I believe you said your timeout is 3 minutes and here it took 3.7221 minutes, I believe you need to increase your timeout?

Yeah that could be the issue on restart. Next time this happens I will disable/unmonitor redis monit and see if the problem persists (bc if not, then this 3 min timeout was the issue)

Regarding why the Redis got unresponsive from the first place, I am still not sure. I kind of suspect this issue: #1470 but I am gone need your help to prove it (or maybe prove that it's not this). Can you do a small script that extracts 'FT.INFO' from all documents each hour (until it will get unresponsive again)? I believe that by analyzing this and see the insertion pattern (amount of documents) over time we will be able to prove if its this or not. If it's not this maybe it will also give us another clew.

Yes, I will do that. But I think it's better to wait for 1.99.4/fixed unlink issue first because maybe the unresponsive issue happens bc redis reaches the max memory limit.

[MeirShpilraien]

@ashtul let's leave it open until we know it was solved

[MeirShpilraien]

@kkmuffme seems like I was wrong about my unlink theory, please do not try the new milestone as it's not fixed there, I am still investigating your aof, will update soon.

[MeirShpilraien]

@kkmuffme this time we got it correctly. The issue was that if a hash is indexed by two indexes and you drop one of them (with delete documents) then we did not get notification about the deletion and we did not clean the second index. this PR should fix it: https://github.com/RediSearch/RediSearch/pull/1483

After the fix, I loaded your AOF and its loaded successfully and only takes 80M memory.

[MeirShpilraien]

@kkmuffme can you test with v1.99.5 and if it's not fixed we will reopen the issue.

[kkmuffme]

Thanks, testing it now and will let you know if the issue happens again after 3-10 days

[MeirShpilraien]

@kkmuffme any updates?

[kkmuffme]

@MeirShpilraien yes the issue didn't happen again and it seems to be working now :+1: