Redisearch performance degrades after a while - needs redis restart

Redis modules RediSearch
1

I saw some very long query times for ft.search on our master redis instance:

“FT.SEARCH” “il1” “@tags:{w\:couchride} @_t:[1594930516 inf]” “LIMIT” “0” “0”

  1. (integer) 3654
    (1.71s) <------------------------

The slowlog was also filled-up with redisearch commands. After restarting the redis db, the latency came back down to normal levels (a few ms for these queries). This was the second time we saw this in our DB - the last time the same query actually took 6s+ before the restart.

Has anyone else experienced this situation?

I am pasting here my ft.info (omitting the schema for brevity) of before/after restart in case someone can spot issues. A lot of values in this info report are way off when comparing the before/after states.

--------- BEFORE RESTART

FT.INFO il1

  1. index_name
  2. il1
  3. index_options
    1. “NOFREQS”
    2. “NOOFFSETS”
  5. fields
  6. …
  7. num_docs
  8. “148518”
  9. max_doc_id
  10. “204979240”
  11. num_terms
  12. “35524”
  13. num_records
  14. “1.8446744070070104e+19”
  15. inverted_sz_mb
  16. “17592186036231.82”
  17. total_inverted_index_blocks
  18. “1514436”
  19. offset_vectors_sz_mb
  20. “0”
  21. doc_table_size_mb
  22. “92.409580230712891”
  23. sortable_values_size_mb
  24. “146.71998596191406”
  25. key_table_size_mb
  26. “4.1586427688598633”
  27. records_per_doc_avg
  28. “124205443607573.17”
  29. bytes_per_record_avg
  30. “1”
  31. offsets_per_term_avg
  32. “0”
  33. offset_bits_per_record_avg
  34. “-nan”
  35. gc_stats
    1. bytes_collected
    2. “91762250”
    3. total_ms_run
    4. “475539”
    5. total_cycles
    6. “91”
    7. avarage_cycle_time_ms
    8. “5225.7032967032965”
    9. last_run_time_ms
10) "7323"
11) gc_numeric_trees_missed
12) "172"
13) gc_blocks_denied
14) "3740"
  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 RESTART

FT.INFO il1

  1. index_name
  2. il1
  3. index_options
    1. “NOFREQS”
    2. “NOOFFSETS”
  5. fields
  6. …
  7. num_docs
  8. “148521”
  9. max_doc_id
  10. “204979321”
  11. num_terms
  12. “35524”
  13. num_records
  14. “1.8446744070070104e+19”
  15. inverted_sz_mb
  16. “17592186036231.822”
  17. total_inverted_index_blocks
  18. “195957”
  19. offset_vectors_sz_mb
  20. “0”
  21. doc_table_size_mb
  22. “12.593805313110352”
  23. sortable_values_size_mb
  24. “20.356704711914062”
  25. key_table_size_mb
  26. “4.1587514877319336”
  27. records_per_doc_avg
  28. “124202934761478.52”
  29. bytes_per_record_avg
  30. “1”
  31. offsets_per_term_avg
  32. “0”
  33. offset_bits_per_record_avg
  34. “-nan”
  35. gc_stats
    1. bytes_collected
    2. “0”
    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) "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
2

Which RediSearch version you are using? Xan you share the redis log file?

3

22292:M 17 Jul 2020 21:26:37.282 * RediSearch version 99.99.99 (Git=v1.6.0-374-g29f3e91c)

The rest of the log file is just rdb dump logging - there are no errors/warnings.

4

You are using an unofficial and a very old commit (from Nov 5, 2019). Please upgrade to 1.6.13 and let me know if the issue continue.

5

Hi Meir, thanks for replying.

I updated to the latest version of redisearch. However, now I get a core-dump immediately when I start redis. I confirm that when I switch back my redisearch to the version I was using, everything works fine.
This is with the latest version of redis 6.0.6
Here is the core-dump:

25393:C 31 Jul 2020 16:10:09.847 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
25393:C 31 Jul 2020 16:10:09.847 # Redis version=6.0.6, bits=64, commit=00000000, modified=0, pid=25393, just started
25393:C 31 Jul 2020 16:10:09.847 # Configuration loaded
25393:M 31 Jul 2020 16:10:09.848 * Increased maximum number of open files to 10032 (it was originally set to 256).
.
.-__ ''-._ _.- . . ‘’-._ Redis 6.0.6 (00000000/0) 64 bit
.- .-```. ```\/ _.,_ ''-._ ( ' , .-` | `, ) Running in standalone mode |`-._`-...-` __...-.-.|’_.-'| Port: 6379 | -. ._ / _.-' | PID: 25393 -._ -._ -./ .-’ .-’
|-._-. -.__.-' _.-'_.-'| | -.-._ _.-'_.-' | http://redis.io -._ -._-..-’.-’ .-’
|-._-. -.__.-' _.-'_.-'| | -.-._ _.-'_.-' | -._ -._-..-’_.-’ _.-’
-._ -..-’ _.-’
-._ _.-' -..-’

25393:M 31 Jul 2020 16:10:09.850 # Server initialized
25393:M 31 Jul 2020 16:10:09.851 * RediSearch version 99.99.99 (Git=v1.99.1-3-g3b4333b2)
25393:M 31 Jul 2020 16:10:09.851 * Low level api version 1 initialized successfully
25393:M 31 Jul 2020 16:10:09.851 * concurrent writes: OFF, gc: ON, prefix min length: 2, prefix max expansions: 200, query timeout (ms): 5000, timeout policy: return, cursor read size: 1000, cursor max idle (ms): 300000, max doctable size: 1000000, search pool size: 20, index pool size: 8,
25393:M 31 Jul 2020 16:10:09.851 * Initialized thread pool!
25393:M 31 Jul 2020 16:10:09.851 * Module ‘ft’ loaded from /Users/michaelmasouras/src/redis-6.0.6/redisearch.so
25393:M 31 Jul 2020 16:10:09.852 * Loading RDB produced by version 5.0.6
25393:M 31 Jul 2020 16:10:09.852 * RDB age 2042 seconds
25393:M 31 Jul 2020 16:10:09.852 * RDB memory usage when created 6039.08 Mb

=== REDIS BUG REPORT START: Cut & paste starting from here ===
25393:M 31 Jul 2020 16:10:11.866 # Redis 6.0.6 crashed by signal: 11
25393:M 31 Jul 2020 16:10:11.867 # Accessing address: 0x0
25393:M 31 Jul 2020 16:10:11.867 # Failed assertion: (:0)

------ STACK TRACE ------
0 redis-server 0x0000000104400f5e logStackTrace + 110
1 redis-server 0x000000010440132d sigsegvHandler + 253
2 libsystem_platform.dylib 0x00007fff6fe1ab5d _sigtramp + 29
3 ??? 0x000000010453aa00 0x0 + 4367559168
4 redis-server 0x00000001043dece1 rdbLoadRio + 1121
5 redis-server 0x00000001043df823 rdbLoad + 227
6 redis-server 0x00000001043b4e8f loadDataFromDisk + 287
7 redis-server 0x00000001043b592e main + 1726
8 libdyld.dylib 0x00007fff6fc2f3d5 start + 1
9 ??? 0x0000000000000002 0x0 + 2

------ INFO OUTPUT ------

Server

redis_version:6.0.6
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:edf0c9c11e932837
redis_mode:standalone
os:Darwin 18.7.0 x86_64
arch_bits:64
multiplexing_api:kqueue
atomicvar_api:atomic-builtin
gcc_version:4.2.1
process_id:25393
run_id:fc0aef842b0366f6297284b4597992b20c9ffdd0
tcp_port:6379
uptime_in_seconds:2
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:2401489
executable:/Users/michaelmasouras/src/redis-6.0.6/src/redis-server
config_file:/Users/michaelmasouras/src/redis-6.0.6/./redis.conf

Clients

connected_clients:0
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
clients_in_timeout_table:0

Memory

used_memory:272717808
used_memory_human:260.08M
used_memory_rss:0
used_memory_rss_human:0B
used_memory_peak:272717808
used_memory_peak_human:260.08M
used_memory_peak_perc:100.36%
used_memory_overhead:61601752
used_memory_startup:1077232
used_memory_dataset:211116056
used_memory_dataset_perc:77.72%
allocator_allocated:0
allocator_active:0
allocator_resident:0
total_system_memory:17179869184
total_system_memory_human:16.00G
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:nan
allocator_frag_bytes:0
allocator_rss_ratio:nan
allocator_rss_bytes:0
rss_overhead_ratio:nan
rss_overhead_bytes:0
mem_fragmentation_ratio:nan
mem_fragmentation_bytes:0
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_clients_slaves:0
mem_clients_normal:0
mem_aof_buffer:0
mem_allocator:libc
active_defrag_running:0
lazyfree_pending_objects:0

Persistence

loading:1
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1596237009
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:0
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
loading_start_time:1596237009
loading_total_bytes:2307191425
loading_loaded_bytes:81788914
loading_loaded_perc:3.54
loading_eta_seconds:54

Stats

total_connections_received:0
total_commands_processed:0
instantaneous_ops_per_sec:0
total_net_input_bytes:0
total_net_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
latest_fork_usec:0
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

Replication

role:master
connected_slaves:0
master_replid:1652b2a4721b705f0c14ae8f327b7c3c4b0f578e
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:0.138793
used_cpu_user:1.866504
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000

Modules

module:name=ft,ver=999999,api=1,filters=0,usedby=,using=,options=

Commandstats

Cluster

cluster_enabled:0

Keyspace

db0:keys=196800,expires=96703,avg_ttl=0

------ CLIENT LIST OUTPUT ------

------ REGISTERS ------
25393:M 31 Jul 2020 16:10:11.868 #
RAX:0000000000000000 RBX:7edfe29dd7b1d00f
RCX:0000000000000002 RDX:00000000019d7d20
RDI:00007ffeeb85b060 RSI:000000000000000f
RBP:00007ffeeb85b100 RSP:00007ffeeb85b038
R8 :0000000000000008 R9 :0000000000000000
R10:0000000000000009 R11:0000000000000009
R12:00007ffeeb85b600 R13:00007fe6d26e93e1
R14:0000000000000007 R15:00007fe6c3c38560
RIP:0000000000000000 EFL:0000000000010206
CS :000000000000002b FS:0000000000000000 GS:0000000000000000
25393:M 31 Jul 2020 16:10:11.868 # (00007ffeeb85b047) -> 00007ffeeb85b100
25393:M 31 Jul 2020 16:10:11.868 # (00007ffeeb85b046) -> 0000000000000007
25393:M 31 Jul 2020 16:10:11.868 # (00007ffeeb85b045) -> 00007ffeeb85b600
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b044) -> 0000000000000007
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b043) -> 00000001043de7c0
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b042) -> 00007ffeeb85b0c0
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b041) -> 0000000000000000
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b040) -> 0000000200000000
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03f) -> 00007fe6c3c38560
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03e) -> 00007ffeeb85b600
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03d) -> 0000000000000000
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03c) -> 00000001044b9e38
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03b) -> 00007ffeeb85b600
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b03a) -> 00007fe6d26e93e1
25393:M 31 Jul 2020 16:10:11.869 # (00007ffeeb85b039) -> 0000000000000004
25393:M 31 Jul 2020 16:10:11.870 # (00007ffeeb85b038) -> 00000001043de2de

------ MODULES INFO OUTPUT ------

=== REDIS BUG REPORT END. Make sure to include from START to END. ===

   Please report the crash by opening an issue on github:

       http://github.com/redis/redis/issues

Suspect RAM error? Use redis-server --test-memory to verify it.

In order to download the latest RS version, I followed the instructions on this page:
https://oss.redislabs.com/redisearch/Quick_Start/

6

One more thing: the server starts fine with the latest version of RS as long as I don’t have my existing dump.rdb file to load.

7

Now you are using master version which is also not the latest nor official version. Please use v1.8.1 tag.

8

I don’t understand - are you suggesting that a core-dump with the latest code is not an issue to be addressed?

9

Sure it is but its a known issue on master currently and we are fixing it.

10

This version is currently the same as master branch:

Known issues in this milestone release:

* Upgrade is not possible from 1.X versions
11

Oh I see, thank you for explaining.

1.8.1 works fine on my system indeed. I 'll start rolling it out slowly into production to see if it addresses the original issue.

1 Like
12

I deployed and run 1.8.1 on production for a few days, and this problem seems to have gone away. Thank you for your help.

2 Likes