Using REPLACE: sortable_values_size_mb and doc_table_size_db growing until maxmemory is hit.

Redis modules RediSearch
1

Hello! Hopefully I’m doing something dumb here - I’m hoping that someone can point it out!

I have about 450k documents, and am upserting approximately 3k per second using the redisearch-py client (0.7.1). Redis is 5.0.1 and Redisearch is 1.4.2. The upserts mostly include keys that are not present in the schema, and they are not always upserting the same keys. There are around 100 keys in my records and I only need to perform autocomplete on a smallish subset of them, but Redis is a convenient place to put those other keys. The DB uses around 20GB - and that’s what it is when I initially load the database. My problem, per the subject is that a few of these tables just continue to grow until I hit my maxmemory - sortable_values_size_mb had gotten up to about 10.5GB at a maxmemory of 28GB. After reloading the DB, those values started small and have been climbing again.

Currently, I am inserting a dictionary like so: rs_client.add_document(id, replace=True, **data)

Is this expected behavior? I am currently using GC_POLICY FORK, as I thought that might help, and am running this on a 4vCPU instance to ensure that GC doesn’t block the Redis thread, but it is a problem either way.

I should note that when I retrieve a document, the keys from multiple upserts are all present - behavior that I would expect from replace partial, not replace without partial. Additionally, I noticed that in ft.info, num_records, inverted_sz_mb, and a few others went crazy when I enabled the gc fork, as you can see below.

In any event, any help would be greatly appreciated!

Thanks,

Dave

7) num_docs
 8) "444846"
 9) max_doc_id
10) "209274516"
11) num_terms
12) "1309914"
13) num_records
14) "1.8446744073672786e+19"
15) inverted_sz_mb
16) "17592186044195.779"
17) offset_vectors_sz_mb
18) "2361.2348375320435"
19) doc_table_size_mb
20) "623.55902194976807"
21) sortable_values_size_mb
22) "1778.0725212097168"
23) key_table_size_mb
24) "15.243436813354492"
25) records_per_doc_avg
26) "41467708091585.742"
27) bytes_per_record_avg
28) "1"
29) offsets_per_term_avg
30) "1.3422066236223884e-10"
31) offset_bits_per_record_avg
32) "8"
33) gc_stats
34)  1) bytes_collected
     2) "500129952"
     3) total_ms_run
     4) "5721826"
     5) total_cycles
     6) "215"
     7) avarage_cycle_time_ms
     8) "26613.144186046513"
     9) last_run_time_ms
    10) "22425"
    11) gc_numeric_trees_missed
    12) "0"
    13) gc_blocks_denied
    14) "1535465"
35) cursor_stats
36) 1) global_idle
    2) (integer) 0
    3) global_total
    4) (integer) 0
    5) index_capacity
    6) (integer) 128
    7) index_total
    8) (integer) 0

``

2

Are you doing upserts at a sustained rate of 3k/sec? It’s possible the forkgc is struggling to keep up. If you don’t want to replace the entire document (but just update a field or two) then you can use the PARTIAL keyword (partial=True), this will avoid a reindex of existing data and eliminate GC for the given update.

I’m unsure how much sortable_value_size is reliable; it seems to never be decremented (probably a bug)… do you have a lot of sortable values? based on the high document ID count, it seems that your upserts are touching an indexed field.

Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

3

I am indeed doing upserts at probably an average of 3k/sec, with peaks around 8-9k. The bulk of the upserts need to replace about 75% of the document, some of which are indexed fields, so I wasn’t sure how much PARTIAL would buy me. Will PARTIAL keep/modify the same document (thus avoiding GC) if new keys or indexed keys are present in the upsert?

FWIW, the sortable_value_size and doc_table_size increases appear closely mapped to used_memory increases. I only have 8 sortable fields, which are all fairly small strings, probably 10-15 characters on average.

4

Yeah, if you need to replace any of the fields, then PARTIAL would not help you. However, it seems we can still do some more cleanup when a document is deleted/removed… Right now, it doesn’t seem as if the metadata is at all cleaned up, hence your massive SORTABLE size.

Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

5

Would you have any other suggestions for remediation at this time? I can’t avoid upserting indexed fields, unfortunately. I can do some aggregation to slow down the rate of upserting - but it seems that in itself won’t resolve the problem.

6

It seems that the leak is in runtime only, so if you save and restart, the leak “resets”; this might be your best options.

You could also try, instead of doing an UPSERT, to manually issue a call to FT.DEL followed by a call to FT.ADD; it might also be necessary to do an FT.GET prior to the FT.DEL if you don’t have all the replacement values upfront. Looking at the code, FT.DEL should clean up the sortable data.

This will also determine if the problem is where I think it is.

Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

7

Ok, in the next day or two I should be able to try the FT.GET/FT.DEL/FT.ADD option and see what kind of performance we can get. I will report back to let you know if that resolves the issue. Thanks!

8

I guess you should use FT.DEL command with DD option in order to delete document reference in the index and also document.

9

So it turns out my epiphany may have been premature, and upon further inspection of the code, it seems that we do properly clean up the references… though there is still a statistics-gathering issue where the SORTABLE size count is never actually decremented. As such, it means that the GET+DEL+ADD cycle may not do what you’d want. If it’s easy enough to try, I’d still give it a shot, in case I’ve missed something.

It might also be possible that you have a lot of empty blocks in the indexes which are just lingering there, this is an issue we are working to resolve in future versions.

Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

10

At this time, I believe that there is not actually any leak. I enabled active defrag, reclaimed a couple GB of space, and bumped up the MAXMEMORY - there were maybe a thousand additional unique documents in my datastream that needed to be ingested into Redis. Memory usage seems to be stable right at 26GB now. FT.INFO stats are still going up, but that is not being reflected in the memory usage any more. Just too much fragmentation, it would seem. Thank you much for your help - I will revive this if memory usage destabilizes.

11

Well, I spoke prematurely - the reason why the DB was stable was that my dataflow had unexpectedly stopped - that’s what I get for trying out an experimental SDK feature. Anyway, after restarting my dataflow job, the problem resumed.

Using a very small pipeline, I am still seeing this issue. Every time I update a document, memory usage goes up. I’ve implemented the GET/DEL/ADD idea, to no avail. I’m running DEL with DD

using redis-py’s Redis.execute_command method, just in case it was an issue with the RediSearch client, and the next command is an add document with the same doc id. FT.INFO shows a stable number of docs and num_terms. num_records fluctuates up and down a little and max_doc_id is incrementing. It looks to me like there may be an issue with DEL - is this possible?

I’m going to try a hail mary and implement partial updates although it seems as though that shouldn’t fix anything.

12

Your use case is kind of rare, normally on search engine you are not doing so many updates, unlike searches which you do a lot.
As mark said I believe you just have a lot of empty (or very small) blocks in the inverted index which the current GC’s (FORK or DEFAULT) are not cleaning/merging. We are planning to fix this issue in future versions.
I would suggest to try the following in order to enforce this hypothesis:
Do not restart the server but instead perform ‘debug reload’, this will perform rdb reload without restarting the server. After rdb reload we are not loading an empty blocks and memory usage should decrease. If this is actually the case it means that our hypothesis is right, if not then we need to keep looking.

13

Yeah, we
needed near-realtime geosearch, among other regularly updating searchable fields
and opted to go with RediSearch because of the upsert performance and generally
the ease of Redis. I attempted a debug reload, and while it did reclaim space,
it was a very small amount:

Before debug reload:

  1. num_docs

  2. “28”

  3. max_doc_id

  4. “4287”

  5. num_terms

  6. “110”

  7. num_records

  8. “143”

  9. inverted_sz_mb

  10. “0.00052928924560546875”

  11. offset_vectors_sz_mb

  12. “0.029620170593261719”

  13. doc_table_size_mb

  14. “0.194915771484375”

  15. sortable_values_size_mb

  16. “0.49474334716796875”

  17. key_table_size_mb

  18. “0.0013256072998046875”

  19. records_per_doc_avg

  20. “5.1071428571428568”

  21. bytes_per_record_avg

  22. “3.8811188811188813”

  23. offsets_per_term_avg

  24. “217.19580419580419”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. current_hz

    2. “6.9339241981506348”

    3. bytes_collected

    4. “62074”

    5. effectiv_cycles_rate

    6. “0.020268099848369192”

  29. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

Memory

used_memory:5217840

used_memory_human:4.98M

used_memory_rss:20955136

used_memory_rss_human:19.98M

used_memory_peak:300472960

used_memory_peak_human:286.55M

used_memory_peak_perc:1.74%

used_memory_overhead:3629862

used_memory_startup:791248

used_memory_dataset:1587978

used_memory_dataset_perc:35.87%

allocator_allocated:17324384

allocator_active:18460672

allocator_resident:33542144

total_system_memory:1039441920

total_system_memory_human:991.29M

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:524288000

maxmemory_human:500.00M

maxmemory_policy:noeviction

allocator_frag_ratio:1.07

allocator_frag_bytes:1136288

allocator_rss_ratio:1.82

allocator_rss_bytes:15081472

rss_overhead_ratio:0.62

rss_overhead_bytes:18446744073696964608

mem_fragmentation_ratio:4.05

mem_fragmentation_bytes:15778312

mem_not_counted_for_evict:0

mem_replication_backlog:1048576

mem_clients_slaves:49686

mem_clients_normal:1555032

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

After debug reload:

  1. num_docs

  2. “28”

  3. max_doc_id

  4. “4288”

  5. num_terms

  6. “110”

  7. num_records

  8. “141”

  9. inverted_sz_mb

  10. “0.0005168914794921875”

  11. offset_vectors_sz_mb

  12. “0.029627799987792969”

  13. doc_table_size_mb

  14. “0.0027332305908203125”

  15. sortable_values_size_mb

  16. “0.007137298583984375”

  17. key_table_size_mb

  18. “0.0013256072998046875”

  19. records_per_doc_avg

  20. “5.0357142857142856”

  21. bytes_per_record_avg

  22. “3.8439716312056738”

  23. offsets_per_term_avg

  24. “220.33333333333334”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. current_hz

    2. “1”

    3. bytes_collected

    4. “16”

    5. effectiv_cycles_rate

    6. “0.0059171597633136093”

  29. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

Memory

used_memory:5164072

used_memory_human:4.92M

used_memory_rss:20566016

used_memory_rss_human:19.61M

used_memory_peak:300472960

used_memory_peak_human:286.55M

used_memory_peak_perc:1.72%

used_memory_overhead:3629862

used_memory_startup:791248

used_memory_dataset:1534210

used_memory_dataset_perc:35.09%

allocator_allocated:17118600

allocator_active:18141184

allocator_resident:28192768

total_system_memory:1039441920

total_system_memory_human:991.29M

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:524288000

maxmemory_human:500.00M

maxmemory_policy:noeviction

allocator_frag_ratio:1.06

allocator_frag_bytes:1022584

allocator_rss_ratio:1.55

allocator_rss_bytes:10051584

rss_overhead_ratio:0.73

rss_overhead_bytes:18446744073701924864

mem_fragmentation_ratio:4.01

mem_fragmentation_bytes:15442960

mem_not_counted_for_evict:0

mem_replication_backlog:1048576

mem_clients_slaves:49686

mem_clients_normal:1555032

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

After reboot (after debug reload):

  1. num_docs

  2. “28”

  3. max_doc_id

  4. “4322”

  5. num_terms

  6. “110”

  7. num_records

  8. “135”

  9. inverted_sz_mb

  10. “0.00047588348388671875”

  11. offset_vectors_sz_mb

  12. “0.029906272888183594”

  13. doc_table_size_mb

  14. “0.0050296783447265625”

  15. sortable_values_size_mb

  16. “0.013184547424316406”

  17. key_table_size_mb

  18. “0.0013256072998046875”

  19. records_per_doc_avg

  20. “4.8214285714285712”

  21. bytes_per_record_avg

  22. “3.6962962962962962”

  23. offsets_per_term_avg

  24. “232.28888888888889”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. bytes_collected

    2. “957”

    3. total_ms_run

    4. “336”

    5. total_cycles

    6. “164”

    7. avarage_cycle_time_ms

    8. “2.0487804878048781”

    9. last_run_time_ms

10) "3"

11) gc_numeric_trees_missed

12) "0"

13) gc_blocks_denied

14) "0"

  1. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

used_memory:2090152

used_memory_human:1.99M

used_memory_rss:7774208

used_memory_rss_human:7.41M

used_memory_peak:2196832

used_memory_peak_human:2.10M

used_memory_peak_perc:95.14%

used_memory_overhead:1027342

used_memory_startup:792336

used_memory_dataset:1062810

used_memory_dataset_perc:81.89%

allocator_allocated:2411616

allocator_active:2867200

allocator_resident:5193728

total_system_memory:1039441920

total_system_memory_human:991.29M

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:524288000

maxmemory_human:500.00M

maxmemory_policy:noeviction

allocator_frag_ratio:1.19

allocator_frag_bytes:455584

allocator_rss_ratio:1.81

allocator_rss_bytes:2326528

rss_overhead_ratio:1.50

rss_overhead_bytes:2580480

mem_fragmentation_ratio:3.83

mem_fragmentation_bytes:5745960

mem_not_counted_for_evict:0

mem_replication_backlog:0

mem_clients_slaves:0

mem_clients_normal:49686

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

14

I’d try doing it with at least several 100k updates. It’s difficult to measure the full impact of the number of terms and whatnot otherwise.
Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

15

Not a problem - here is the same on our larger pipeline:

Before debug reload:

Memory

used_memory:40076187152

used_memory_human:37.32G

used_memory_rss:43420045312

used_memory_rss_human:40.44G

used_memory_peak:40077586616

used_memory_peak_human:37.33G

used_memory_peak_perc:100.00%

used_memory_overhead:132725850

used_memory_startup:791312

used_memory_dataset:39943461302

used_memory_dataset_perc:99.67%

allocator_allocated:40087827776

allocator_active:41542266880

allocator_resident:42250883072

total_system_memory:84471541760

total_system_memory_human:78.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:40802189312

maxmemory_human:38.00G

maxmemory_policy:noeviction

allocator_frag_ratio:1.04

allocator_frag_bytes:1454439104

allocator_rss_ratio:1.02

allocator_rss_bytes:708616192

rss_overhead_ratio:1.03

rss_overhead_bytes:1169162240

mem_fragmentation_ratio:1.08

mem_fragmentation_bytes:3343539480

mem_not_counted_for_evict:0

mem_replication_backlog:33554432

mem_clients_slaves:16914

mem_clients_normal:10856784

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

  1. num_docs

  2. “448639”

  3. max_doc_id

  4. “284353645”

  5. num_terms

  6. “1319683”

  7. num_records

  8. “1.8446744073524658e+19”

  9. inverted_sz_mb

  10. “17592186043274.912”

  11. offset_vectors_sz_mb

  12. “3207.3950719833374”

  13. doc_table_size_mb

  14. “94.697874069213867”

  15. sortable_values_size_mb

  16. “269.68108749389648”

  17. key_table_size_mb

  18. “15.379879951477051”

  19. records_per_doc_avg

  20. “41117121056594.617”

  21. bytes_per_record_avg

  22. “1”

  23. offsets_per_term_avg

  24. “1.8231929854728435e-10”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. bytes_collected

    2. “41420087”

    3. total_ms_run

    4. “450668”

    5. total_cycles

    6. “5”

    7. avarage_cycle_time_ms

    8. “90133.600000000006”

    9. last_run_time_ms

10) "117463"

11) gc_numeric_trees_missed

12) "0"

13) gc_blocks_denied

14) "341000"

  1. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

After debug reload:

Memory

used_memory:40112706392

used_memory_human:37.36G

used_memory_rss:43426922496

used_memory_rss_human:40.44G

used_memory_peak:40130550000

used_memory_peak_human:37.37G

used_memory_peak_perc:99.96%

used_memory_overhead:126617844

used_memory_startup:791312

used_memory_dataset:39986088548

used_memory_dataset_perc:99.69%

allocator_allocated:40123954112

allocator_active:41556844544

allocator_resident:42243977216

total_system_memory:84471541760

total_system_memory_human:78.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:40802189312

maxmemory_human:38.00G

maxmemory_policy:noeviction

allocator_frag_ratio:1.04

allocator_frag_bytes:1432890432

allocator_rss_ratio:1.02

allocator_rss_bytes:687132672

rss_overhead_ratio:1.03

rss_overhead_bytes:1182945280

mem_fragmentation_ratio:1.08

mem_fragmentation_bytes:3314490608

mem_not_counted_for_evict:0

mem_replication_backlog:33554432

mem_clients_slaves:16914

mem_clients_normal:4739178

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

  1. num_docs

  2. “448695”

  3. max_doc_id

  4. “284577197”

  5. num_terms

  6. “1319846”

  7. num_records

  8. “1.8446744073522645e+19”

  9. inverted_sz_mb

  10. “17592186043261.812”

  11. offset_vectors_sz_mb

  12. “3209.8835334777832”

  13. doc_table_size_mb

  14. “48.904885292053223”

  15. sortable_values_size_mb

  16. “140.50869178771973”

  17. key_table_size_mb

  18. “15.381827354431152”

  19. records_per_doc_avg

  20. “41111989377438.016”

  21. bytes_per_record_avg

  22. “1”

  23. offsets_per_term_avg

  24. “1.824607548384094e-10”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. bytes_collected

    2. “12890527”

    3. total_ms_run

    4. “47507”

    5. total_cycles

    6. “1”

    7. avarage_cycle_time_ms

    8. “47507”

    9. last_run_time_ms

10) "47507"

11) gc_numeric_trees_missed

12) "0"

13) gc_blocks_denied

14) "45365"

  1. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

After reboot:

Memory

used_memory:33515657216

used_memory_human:31.21G

used_memory_rss:34328510464

used_memory_rss_human:31.97G

used_memory_peak:33515837064

used_memory_peak_human:31.21G

used_memory_peak_perc:100.00%

used_memory_overhead:486054040

used_memory_startup:791312

used_memory_dataset:33029603176

used_memory_dataset_perc:98.55%

allocator_allocated:33516136520

allocator_active:33611100160

allocator_resident:34065416192

total_system_memory:84471541760

total_system_memory_human:78.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:40802189312

maxmemory_human:38.00G

maxmemory_policy:noeviction

allocator_frag_ratio:1.00

allocator_frag_bytes:94963640

allocator_rss_ratio:1.01

allocator_rss_bytes:454316032

rss_overhead_ratio:1.01

rss_overhead_bytes:263094272

mem_fragmentation_ratio:1.02

mem_fragmentation_bytes:812673400

mem_not_counted_for_evict:353632488

mem_replication_backlog:33554432

mem_clients_slaves:353649402

mem_clients_normal:10537566

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

  1. num_docs

  2. “448715”

  3. max_doc_id

  4. “284738085”

  5. num_terms

  6. “1319899”

  7. num_records

  8. “1.8446744073522229e+19”

  9. inverted_sz_mb

  10. “17592186043259.074”

  11. offset_vectors_sz_mb

  12. “3211.6904602050781”

  13. doc_table_size_mb

  14. “48.592517852783203”

  15. sortable_values_size_mb

  16. “139.6281623840332”

  17. key_table_size_mb

  18. “15.382501602172852”

  19. records_per_doc_avg

  20. “41110156945298.359”

  21. bytes_per_record_avg

  22. “1”

  23. offsets_per_term_avg

  24. “1.8256346434597504e-10”

  25. offset_bits_per_record_avg

  26. “8”

  27. gc_stats

    1. bytes_collected

    2. “6919164”

    3. total_ms_run

    4. “0”

    5. total_cycles

    6. “0”

    7. avarage_cycle_time_ms

    8. “-nan”

    9. last_run_time_ms

10) "0"

11) gc_numeric_trees_missed

12) "0"

13) gc_blocks_denied

14) "43596"

  1. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

    5. index_capacity

    6. (integer) 128

    7. index_total

    8. (integer) 0

16

Thank you

At this point, we are suspecting a runtime leak in RediSearch, because of the difference in the memory used after DEBUG RELOAD and after a reboot. To help us better debug this information:

(1) Can you please write a script that demonstrates the kind of workload you’re executing. While we can approximate an upsert here, it’s important to know which fields are being updated when, because there are multiple code paths.

(2) Also try FLUSHALL or FLUSHDB instead of (or after) DEBUG RELOAD, and let’s see the INFO output. The remaining memory is the amount that’s being leaked.

Regards,
Mark Nunberg | Senior Software Engineer
Redis Labs - home of Redis

Email: mark@redislabs.com

17

I think you are on to something. Here’s the info before/after FLUSHALL, and I will get back to you with that script:

Before FLUSHALL:

Server

redis_version:5.0.1

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:678e98ad35fb9585

redis_mode:standalone

os:Linux 4.14.74+ x86_64

arch_bits:64

multiplexing_api:epoll

atomicvar_api:atomic-builtin

gcc_version:6.3.0

process_id:10

run_id:1fbb11439544b7ceb72ecad2604942670db3412c

tcp_port:6379

uptime_in_seconds:7387

uptime_in_days:0

hz:10

configured_hz:10

lru_clock:5467258

executable:/opt/rs-project/redis-server

config_file:/opt/rs-project/redis.conf

Clients

connected_clients:1787

client_recent_max_input_buffer:4

client_recent_max_output_buffer:0

blocked_clients:14

Memory

used_memory:34360784664

used_memory_human:32.00G

used_memory_rss:35347845120

used_memory_rss_human:32.92G

used_memory_peak:35884029800

used_memory_peak_human:33.42G

used_memory_peak_perc:95.76%

used_memory_overhead:157674526

used_memory_startup:791312

used_memory_dataset:34203110138

used_memory_dataset_perc:99.54%

allocator_allocated:34363255744

allocator_active:34500288512

allocator_resident:34981470208

total_system_memory:84471541760

total_system_memory_human:78.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:40802189312

maxmemory_human:38.00G

maxmemory_policy:noeviction

allocator_frag_ratio:1.00

allocator_frag_bytes:137032768

allocator_rss_ratio:1.01

allocator_rss_bytes:481181696

rss_overhead_ratio:1.01

rss_overhead_bytes:366374912

mem_fragmentation_ratio:1.03

mem_fragmentation_bytes:986063752

mem_not_counted_for_evict:0

mem_replication_backlog:33554432

mem_clients_slaves:0

mem_clients_normal:35731014

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:0

lazyfree_pending_objects:0

Persistence

loading:0

rdb_changes_since_last_save:1147482

rdb_bgsave_in_progress:0

rdb_last_save_time:1548970649

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:138

rdb_current_bgsave_time_sec:-1

rdb_last_cow_size:3279900672

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:306045

total_commands_processed:53546399

instantaneous_ops_per_sec:3521

total_net_input_bytes:33600036484

total_net_output_bytes:43489342601

instantaneous_input_kbps:4293.19

instantaneous_output_kbps:63.06

rejected_connections:0

sync_full:8

sync_partial_ok:0

sync_partial_err:7

expired_keys:0

expired_stale_perc:0.00

expired_time_cap_reached_count:0

evicted_keys:0

keyspace_hits:55403660

keyspace_misses:592

pubsub_channels:0

pubsub_patterns:0

latest_fork_usec:916526

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

Replication

role:master

connected_slaves:0

master_replid:3eefae3c53352a1e03afde1a028201132b5b5f78

master_replid2:0000000000000000000000000000000000000000

master_repl_offset:31964389624

second_repl_offset:-1

repl_backlog_active:1

repl_backlog_size:33554432

repl_backlog_first_byte_offset:31930835193

repl_backlog_histlen:33554432

CPU

used_cpu_sys:2037.640381

used_cpu_user:4674.167834

used_cpu_sys_children:1118.491446

used_cpu_user_children:2087.244725

Cluster

cluster_enabled:0

Keyspace

db0:keys=1770513,expires=0,avg_ttl=0

  1. index_name

  2. fixmyzonar-latest

  3. index_options

  4. (empty list or set)

  5. fields

      1. field_1

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_2

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_3

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_4

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_5

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_6

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_7

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_8

      2. type

      3. TEXT

      4. WEIGHT

      5. “1”

      6. SORTABLE

      1. field_9

      2. type

      3. GEO

  7. num_docs

  8. “449289”

  9. max_doc_id

  10. “291230962”

  11. num_terms

  12. “1321220”

  13. num_records

  14. “1.8446744073510504e+19”

  15. inverted_sz_mb

  16. “17592186043188.352”

  17. offset_vectors_sz_mb

  18. “3285.8612232208252”

  19. doc_table_size_mb

  20. “624.39939594268799”

  21. sortable_values_size_mb

  22. “1779.861611366272”

  23. key_table_size_mb

  24. “15.402425765991211”

  25. records_per_doc_avg

  26. “41057635672606.164”

  27. bytes_per_record_avg

  28. “1”

  29. offsets_per_term_avg

  30. “1.867795917931403e-10”

  31. offset_bits_per_record_avg

  32. “8”

  33. gc_stats

    1. bytes_collected

    2. “519210748”

    3. total_ms_run

    4. “5069638”

    5. total_cycles

    6. “193”

    7. avarage_cycle_time_ms

    8. “26267.554404145078”

    9. last_run_time_ms

10) "20503"

11) gc_numeric_trees_missed

12) "0"

13) gc_blocks_denied

14) "1598860"

  1. cursor_stats

    1. global_idle

    2. (integer) 0

    3. global_total

    4. (integer) 0

After FLUSHALL:

Server

redis_version:5.0.1

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:678e98ad35fb9585

redis_mode:standalone

os:Linux 4.14.74+ x86_64

arch_bits:64

multiplexing_api:epoll

atomicvar_api:atomic-builtin

gcc_version:6.3.0

process_id:10

run_id:1fbb11439544b7ceb72ecad2604942670db3412c

tcp_port:6379

uptime_in_seconds:8087

uptime_in_days:0

hz:10

configured_hz:10

lru_clock:5467958

executable:/opt/zonar/fixmyzonar-redis/redis-server

config_file:/opt/zonar/fixmyzonar-redis/redis.conf

Clients

connected_clients:357

client_recent_max_input_buffer:2

client_recent_max_output_buffer:0

blocked_clients:0

Memory

used_memory:641325960

used_memory_human:611.62M

used_memory_rss:2088706048

used_memory_rss_human:1.95G

used_memory_peak:35884029800

used_memory_peak_human:33.42G

used_memory_peak_perc:1.79%

used_memory_overhead:44497456

used_memory_startup:791312

used_memory_dataset:596828504

used_memory_dataset_perc:93.18%

allocator_allocated:643809856

allocator_active:1050882048

allocator_resident:1659817984

total_system_memory:84471541760

total_system_memory_human:78.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:40802189312

maxmemory_human:38.00G

maxmemory_policy:noeviction

allocator_frag_ratio:1.63

allocator_frag_bytes:407072192

allocator_rss_ratio:1.58

allocator_rss_bytes:608935936

rss_overhead_ratio:1.26

rss_overhead_bytes:428888064

mem_fragmentation_ratio:3.26

mem_fragmentation_bytes:1447425824

mem_not_counted_for_evict:0

mem_replication_backlog:33554432

mem_clients_slaves:16914

mem_clients_normal:10134798

mem_aof_buffer:0

mem_allocator:jemalloc-5.1.0

active_defrag_running:46

lazyfree_pending_objects:0

Persistence

loading:0

rdb_changes_since_last_save:0

rdb_bgsave_in_progress:0

rdb_last_save_time:1548971796

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:0

rdb_current_bgsave_time_sec:-1

rdb_last_cow_size:46399488

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:307530

total_commands_processed:56151788

instantaneous_ops_per_sec:13015

total_net_input_bytes:36736979509

total_net_output_bytes:43541705543

instantaneous_input_kbps:32258.78

instantaneous_output_kbps:165.21

rejected_connections:0

sync_full:10

sync_partial_ok:0

sync_partial_err:8

expired_keys:0

expired_stale_perc:0.00

expired_time_cap_reached_count:0

evicted_keys:0

keyspace_hits:57647294

keyspace_misses:408412

pubsub_channels:0

pubsub_patterns:0

latest_fork_usec:169870

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

Replication

role:master

connected_slaves:1

slave0:ip=10.140.0.61,port=6379,state=online,offset=0,lag=24

master_replid:3eefae3c53352a1e03afde1a028201132b5b5f78

master_replid2:0000000000000000000000000000000000000000

master_repl_offset:34216051012

second_repl_offset:-1

repl_backlog_active:1

repl_backlog_size:33554432

repl_backlog_first_byte_offset:34182496581

repl_backlog_histlen:33554432

CPU

used_cpu_sys:2141.908940

used_cpu_user:5259.850778

used_cpu_sys_children:1179.108393

used_cpu_user_children:2243.544968

Cluster

cluster_enabled:0

18

Here’s a script that reproduces the issue:

from datetime import datetime

from random import random, randint, shuffle

import redis

import redisearch

from redisearch import TextField, GeoField

SCHEMA = [

TextField('small_field_field_1', sortable=True),

TextField('small_field_field_2', sortable=True),

TextField('small_field_field_3', sortable=True),

TextField('small_field_field_4', sortable=True),

TextField('small_field_field_5', sortable=True),

TextField('small_field_field_6', sortable=True),

TextField('small_field_field_7', sortable=True),

TextField('small_field_field_8', sortable=True),

GeoField('geo'),

]

def get_messages():

"""Return message queue, which may be out of order."""

msg_queue = []

for _ in range(10000):

    # Some values are a more significant size, i.e. 1KB

    msg = {

        'small_field_name_{}'.format(x):

        'often_a_small_value_{}'.format(str(random())) for x in range(120)

    }

    msg['geo'] = '{0},{0}'.format(random())

    # If you tune down the number of keys, i.e. create more actual upserts,

    # it is easier to observe how memory usage climbs during runtime,

    # regardless of document count.

    msg['key'] = str(randint(0, 500000))

    msg['ts'] = str(datetime.utcnow())

    msg_queue.append(msg)

shuffle(msg_queue)

return msg_queue

def run():

"""Upsert messages if they have more recent data than Redis."""

r = redis.Redis()

rs = redisearch.Client('index', conn=r)

rs.create_index(SCHEMA)

while True:

    msg_queue = get_messages()

    for msg in msg_queue:

        new_ts = datetime.strptime(msg['ts'], '%Y-%m-%d %H:%M:%S.%f')

        try:

            old_ts = datetime.strptime(

                r.hget(msg['key'], 'ts'), '%Y-%m-%d %H:%M:%S.%f')

        except TypeError:

            old_ts = None

        if not old_ts or new_ts > old_ts:

            rs.add_document(msg['key'], replace=True, partial=True, **msg)

        # This script exhibits the symptom without this, but just in case,

        # occasionally values are added directly to a hash, i.e:

        # if not randint(0, 10):

        #     r.hset(msg['key'], 'another key', 'some other value')

if name == ‘main’:

run()

``

The leftover after a FLUSHALL appears minor after running this locally for a few minutes - only maybe 10-20KB and clearly doesn’t account for the entire leak during upserts, which goes up much more rapidly. It still adds up though, the 611MB of leftover on our large pipe accumulated over two-three weeks. Please let me know if I can do something else.

19

Forgive my fat-fingering, I noticed I misnamed the schema keys (corrected below), those should be a part of the messages. Even so, the script still exhibited the issue.

from datetime import datetime

from random import random, randint, shuffle

import redis

import redisearch

from redisearch import TextField, GeoField

SCHEMA = [

TextField(‘small_field_name_1’, sortable=True),

TextField(‘small_field_name_2’, sortable=True),

TextField(‘small_field_name_3’, sortable=True),

TextField(‘small_field_name_4’, sortable=True),

TextField(‘small_field_name_5’, sortable=True),

TextField(‘small_field_name_6’, sortable=True),

TextField(‘small_field_name_7’, sortable=True),

TextField(‘small_field_name_8’, sortable=True),

GeoField(‘geo’),

]

def get_messages():

“”“Return message queue, which may be out of order.”""

msg_queue = []

for _ in range(10000):

   # Some values are a more significant size, i.e. 1KB

   msg = {

       'small_field_name_{}'.format(x):

       'often_a_small_value_{}'.format(str(random())) for x in range(120)

   }

   msg['geo'] = '{0},{0}'.format(random())

   # If you tune down the number of keys, i.e. create more actual upserts,

   # it is easier to observe how memory usage climbs during runtime,

   # regardless of document count.

   msg['key'] = str(randint(0, 500000))

   msg['ts'] = str(datetime.utcnow())

   msg_queue.append(msg)

shuffle(msg_queue)

return msg_queue

def run():

“”“Upsert messages if they have more recent data than Redis.”""

r = redis.Redis()

rs = redisearch.Client(‘index’, conn=r)

rs.create_index(SCHEMA)

while True:

   msg_queue = get_messages()

   for msg in msg_queue:

       new_ts = datetime.strptime(msg['ts'], '%Y-%m-%d %H:%M:%S.%f')

       try:

           old_ts = datetime.strptime(

               r.hget(msg['key'], 'ts'), '%Y-%m-%d %H:%M:%S.%f')

       except TypeError:

           old_ts = None

        if not old_ts or new_ts > old_ts:

           rs.add_document(msg['key'], replace=True, partial=True, **msg)

       # This script exhibits the symptom without this, but just in case,

       # occasionally values are added directly to a hash, i.e:

       # if not randint(0, 10):

       #     r.hset(msg['key'], 'another key', 'some other value')

if name == ‘main’:

run()

``

``

20

Hey,
Thanks for the scrip, we will look into it.

Regardless, I see you are using geo tag, we just found an issue recently that the geo index is not been cleaned properly on updates (only on actual delete), so this might be an issue.
Second we just release 1.4.3 with a more stable FORK GC, you can try it maybe it will improve the memory usage a little.