Redis Streams with Consumer Groups and memory management.

[vsouza]

Hi everyone. I'm facing some issues to deal with the memory increase in Redis 5.0.9. Our setup consists of 3 VM's, master, slave, and a Sentinel.

Our application pipeline consists in:

XADD mystream * sensor-id 1234 temperature 19.8

We work with 12 different streams.

XREADGROUP GROUP mygroup Alice COUNT 150 STREAMS mystream >

XTRIM 500000 mystream

We understand that Redis does not release memory instantly using the XDEL command. So we changed to use XTRIM and evict OOM errors.

Analyzing our metrics, we detected a correlation between XREADGROUP commands and memory increase. Remembering that we perform an XTRIM command. But memory continues to increase.

Some data to help us discover what going on:

The slave node doesn't increase memory equal master node, our replication is working fine.
We are using Golang client with MinConnIdle config was set as 100 per host. (our default is 10 nodes).
Our number of consumers is about 10 per consumer node (about 6 nodes dedicated to consumers).
Looking for pending messages is zero. XLEN of our streams is equal to XTRIM value.
Our XADD rate is about 6k per second.

Redis INFO:

# Server
redis_version:5.0.9
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:3d4d32bb8c35cf6a
redis_mode:standalone
os:Linux 4.1.12-61.1.28.el6uek.x86_64 x86_64
arch_bits:64
multiplexing_api:epoll
atomicvar_api:sync-builtin
gcc_version:4.4.7
process_id:26640
run_id:b50f2a78f33faa60d6d2cf48a6939aac075fcc34
tcp_port:6379
uptime_in_seconds:177932
uptime_in_days:2
hz:20
configured_hz:10
lru_clock:4794776
executable:/usr/local/redis/src/redis-server
config_file:/data/redis.conf

# Clients
connected_clients:2136
client_recent_max_input_buffer:4
client_recent_max_output_buffer:123072
blocked_clients:45

# Memory
used_memory:7442392864
used_memory_human:6.93G
used_memory_rss:7431725056
used_memory_rss_human:6.92G
used_memory_peak:7452463192
used_memory_peak_human:6.94G
used_memory_peak_perc:99.86%
used_memory_overhead:1114066798
used_memory_startup:783544
used_memory_dataset:6328326066
used_memory_dataset_perc:85.04%
allocator_allocated:7442401520
allocator_active:7460909056
allocator_resident:7569297408
total_system_memory:33461932032
total_system_memory_human:31.16G
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:25769803776
maxmemory_human:24.00G
maxmemory_policy:volatile-lru
allocator_frag_ratio:1.00
allocator_frag_bytes:18507536
allocator_rss_ratio:1.01
allocator_rss_bytes:108388352
rss_overhead_ratio:0.98
rss_overhead_bytes:-137572352
mem_fragmentation_ratio:1.00
mem_fragmentation_bytes:-10407736
mem_not_counted_for_evict:0
mem_replication_backlog:1073741824
mem_clients_slaves:16922
mem_clients_normal:39523900
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:1112266617
rdb_bgsave_in_progress:0
rdb_last_save_time:1615229752
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_current_bgsave_time_sec:-1
rdb_last_cow_size:294912
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:9213369
total_commands_processed:575153203
instantaneous_ops_per_sec:4189
total_net_input_bytes:374022659065
total_net_output_bytes:718721749681
instantaneous_input_kbps:2587.72
instantaneous_output_kbps:5761.27
rejected_connections:0
sync_full:1
sync_partial_ok:0
sync_partial_err:1
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
evicted_keys:0
keyspace_hits:22961146
keyspace_misses:3707
pubsub_channels:1
pubsub_patterns:0
latest_fork_usec:368
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
master_replid:ba3b6fd43ed2f0f336b4166e3a2ee5060a1151c5
master_replid2:ceccbc431f46f04ea7c32882de68c26d1f1f6c3b
master_repl_offset:8873053474828
second_repl_offset:8443132203955
repl_backlog_active:1
repl_backlog_size:1000000000
repl_backlog_first_byte_offset:8872053474829
repl_backlog_histlen:1000000000

# CPU
used_cpu_sys:22945.887250
used_cpu_user:24607.789431
used_cpu_sys_children:0.001750
used_cpu_user_children:0.000000

# Cluster
cluster_enabled:0

# Keyspace
db0:keys=12,expires=0,avg_ttl=0

[itamarhaber]

Hello @vsouza

If I understand correctly, the reason for submitting this issue is that the replica's memory usage doesn't correspond to that of the master's, and that there appears to be an increase in the master's memory usage. If so, please share the full output of INFO all's from both master and replica taken approximately at the same time so it can be demonstrated.

Also, it would be helpful, if possible, to see these metrics over time and the correlation you've identified.

One thing that does stand out above is the master's 1GB replication backlog (and the fact there's only a single replica), which means there's an active (slow?) sync going on.

[hwware]

@vsouza I found this issue disappeared in 5.0.10 version. After I check the difference between 5.0.9 and 5.0.10, I found it was solved in the commit a3ca53e
@itamarhaber @oranagra @yossigo Could you please provide more background for this commit? Thanks a lot

[oranagra]

The background is that alsoPropagate only worked in the context of call so when used in an blocked command (when it gets unblocked), it would have been ignored.

IIRC this commit is related some to some issue or PR that @guybe7 opened.

[mohoch1]

We are experiencing a similar issue with Redis version 6.2.7.
We have a cluster with 4 master nodes and 4 slave nodes.

All the keys are written and expire as expected, and the memory usage is stable.
But when we use the Redis Streams, the memory keeps building up.
With each XADD we also put XTRIM with MAXLEN 10000 and this limit is actually enforced. But gradually the memory usage increases, although the number of messages and their size are constant.

The node holding this key reached 19GB and more, even when no other key was stored on that node.

Applying a XTRIM of 10 reduced the number of messages, but not the memory.

The only way to take down the memory, was to DEL the key.

Any idea?

[oranagra]

@mohoch1 please share your config, specifically stream-node-max-entries and stream-node-max-bytes.
also, maybe can share XINFO STREAM <key> on that key when it has very few entries and holds huge amount of memory.
i also wonder what MEMORY USAGE <key> says on that key.
@guybe7 do you have any other ideas?

[mohoch1]

Hi.

1. the config value for stream-node-max-entries is 100
2. the config value for stream-node-max-bytes is 4096 (which is the default)
3. I cleared the stream and let it run for a while. Using Redis Insight memory analyzer, I can see that with 150 entries the key's memory usage is over 800 MB, while the overall node usage is still over 3 GB (when this is the only key on the node)
4. An example of XINFO STREAM <key> with only 40 entries:

1. "length"

2. (integer) 40

3. "radix-tree-keys"

4. (integer) 4

5. "radix-tree-nodes"

6. (integer) 10

7. "last-generated-id"

8. "1681645685860-0"

9. "groups"

10. (integer) 1

11. "first-entry"

12. 1. "1681645682372-0"
    2. 1. "database"
       2. "default"
       3. "names"
       4. "my-stats"
       5. "time"
       6. "2023-04-16 11:48:02"
       7. "tags"
       8. "{"machine-name":"MACHINE-NAME-04","process-name":"MY.AgentService","process-id":27036}"
       9. "fields"
    3. "{"retrievals":0,"retrieval-duration-max":0,"retrieval-duration-min":0,"retrieval-duration-avg":0,"retrievalErrors":0,"lockTimeouts":0,"lock-duration-max":0}"

13. "last-entry"

14. 1. "1681645685860-0"
    2. 1. "database"
       2. "default"
       3. "names"
       4. "my-stats"
       5. "time"
       6. "2023-04-16 11:48:05"
       7. "tags"
       8. "{"machine-name":"MACHINE-NAME-02","process-name":"MY.AgentService","process-id":35784}"
       9. "fields"
    3. "{"retrievals":0,"retrieval-duration-max":0,"retrieval-duration-min":0,"retrieval-duration-avg":0,"retrievalErrors":0,"lockTimeouts":0,"lock-duration-max":0}"

[rishbard]

Hi @mohoch1 we're facing a similar problem with our ElasticCache cluster.

Can you confirm if you have activedefrag parameter set to true for your cluster? Could that play a role in the memory not being cleared for stream/s after XTRIM.

[oranagra]

activedefrag can fix problems with allocator_frag_bytes, and some cases of high RSS, but in this case it's in used_memory, so it's either a leak, or some inefficiency in the stream stricture (not fragmentation).
considering that it is released when deleting the key, then it's not a leak.

[guybe7]

@mohoch1 let's try to narrow down the problem... do you use consumer groups? can you try do build the same scenario without consumer groups?

one theory is that once an entry has been read by a consumer and is held in a PEL, it is not trimmed even if the original entry in the actual stream rax was trimmed

[mohoch1]

@guybe7, yes I am reading the stream using a consumer group.
I will try to remove that, as this is indeed not required in my scenario.

I will update after we finish checking.

Thanks.

[mohoch1]

Well - consuming without a consumer group did not help.
We are seeing the same memory leak

[piavgh]

@mohoch1 : we are facing the same issue with Redis v7
What is your solution?

[mohoch1]

Actually, for now I don't have any solution.
From time to time I just delete the stream.

[guybe7]

@mohoch1 what do you mean by "consuming without a consumer group"?

AFAICT it is true that deleting/trimming unacknowledged entries will not free the NACK entries from the PELs - but this is most likely by design - you should not delete/trim entries that were consumed by a consumer and not acknowledged (feels like a bug in the application? why would you delete an entry before the consumer processed it?)

a nasty workaround is to use XAUTOCLAIM every once in a while (XAUTOCLAIM will clear any deleted entries it stumbles upon from the PEL)

[oranagra]

@mohoch1 please post the output of XINFO GROUPS <key>, so we can see if it's an ACK problem or something else.