Memory usage when replaying messages with filter subject on a large stream

[david-wakeo]

Hi,

I am observing a sudden memory explosion on our nats servers when we replay some messages from a (large?) stream with a filter subject.
When it happens, the memory reaches within seconds the upper 1.5 GiB limits (defined with GO_MEMORY_LIMITS) with the following effects:

• at best it's just a slower
• usually there are timeouts
• at worst, some clients lose connections

I'd like to know if:

• the memory behavior is expected given the size of the stream and I just need to allocate more resource to the servers
• jetstream is not designed for this kind of usage
• there may be an issue in the server configuration
• there may be a bug and I need to investigate deeper to try to reproduce it and then report it

Here is the stream configuration

Configuration:

      Description: ***
             Subjects: domain.*.resource.>
     Acknowledgements: true
            Retention: File - Limits
             Replicas: 3
       Discard Policy: Old
     Duplicate Window: 2m0s
     Maximum Messages: unlimited
        Maximum Bytes: 10 GiB
          Maximum Age: 14d0h0m0s
 Maximum Message Size: unlimited
    Maximum Consumers: unlimited


Cluster Information:

                 Name: ***
               Leader: ***
              Replica: ***, current, seen 0.35s ago
              Replica: ***, current, seen 0.35s ago

State:

             Messages: 2,425,521
                Bytes: 7.3 GiB
             FirstSeq: 4,551,098 @ 2023-12-07T14:19:44 UTC
              LastSeq: 6,976,618 @ 2023-12-21T14:19:44 UTC
     Active Consumers: 4

The {domain} part of the subject is fixed
The {resource} part of the subject is uuid like

The problem is reproducible with the cli or nats.js whenever we want to retrieve the messages of a specific {resource}

# from cli
nats stream view THE_STREAM  --subject='domain.*.specific_uuid.*'

# from nats.js
const subject = `domain.*.{specific_uuid}.*`
const consumer = await this.jsc.consumers.get(stream, {
    filterSubjects: subject,
})
const callback = (m: JsMsg) => {
   ...
}
const messages = await consumer.consume({ callback })

Last closing observations:

• it appears to be more prevalent when the resource is recent that is when the first retrieved message is at the end of the stream
• it appears it's related to the stream size, it was not visible when the stream was at 1 GiB size and appears to be more prevalent now the stream is at 7 GiB size
• putting the GO_MEMORY_LIMITS was helpful but it's no longer enough to prevent the side effects on other consumers
• it helps if we set a deliver policy with a recent start_date; if the date is within a day there are no issues (but we may miss some messages obviously)

Thanks!

[derekcollison]

Is your consumer flow controlled at all via MaxAckPending or some other mechanism?
What server version?
What does nats consumer info show for the consumer during replay?
Do you have the profiling enabled? Can you grab a memory profile?

[david-wakeo]

Thanks for the answer

Is your consumer flow controlled at all via MaxAckPending or some other mechanism?

In either case, I didn't specify anything regarding the consumer so I expect it to behave like an Ordered consumer. But I don't really know how each client decides to implement the flow control. I guess it will show through the consumer information?

What server version?

2.10.5

What does nats consumer info show for the consumer during replay?

Consumer from nats.js

? Select a Consumer 6GXJF9EVXWJF2OTY2A2JQW_1
Information for Consumer STREAM_NAME > 6GXJF9EVXWJF2OTY2A2JQW_1 created 2023-12-21T17:00:48+01:00

Configuration:

           Pull Mode: true
      Filter Subject: {domain}.*.channel.uuid.*
      Deliver Policy: From Sequence 1
          Ack Policy: None
       Replay Policy: Instant
   Max Waiting Pulls: 512

Cluster Information:

                Name: ***
              Leader: ***

State:

   Last Delivered Message: Consumer sequence: 51 Stream sequence: 6993247 Last delivery: 4.52s ago
     Unprocessed Messages: 0
            Waiting Pulls: 3 of maximum 512

Consumer from the cli

Information for Consumer STREAM_NAME > jsm_stream_pager_2941261703174062936072602 created 2023-12-21T16:54:22+01:00

Configuration:

        Durable Name: jsm_stream_pager_2941261703174062936072602
         Description: JSM Stream Pager
           Pull Mode: true
      Filter Subject: domain.*.channel.uuid.*
      Deliver Policy: All
          Ack Policy: Explicit
            Ack Wait: 30s
       Replay Policy: Instant
     Max Ack Pending: 1,000
   Max Waiting Pulls: 512

Cluster Information:

                Name: ***
              Leader: ***
             Replica: ***, current, seen 0.41s ago
             Replica: ***, current, seen 0.41s ago

State:

   Last Delivered Message: Consumer sequence: 10 Stream sequence: 4812225 Last delivery: 10.14s ago
     Acknowledgment floor: Consumer sequence: 10 Stream sequence: 4812225 Last Ack: 10.03s ago
         Outstanding Acks: 0 out of maximum 1000
     Redelivered Messages: 0
     Unprocessed Messages: 65
            Waiting Pulls: 0 of maximum 512

Please note that during the operation, there was an error during not consumers retrieval (after a noticeable delay)

❯ nats consumer info  STREAM NAME
nats: error: could not select Stream: context deadline exceeded

And here is the graph on memory impact (100% = 2 GiB)

Do you have the profiling enabled? Can you grab a memory profile?

I don't have profile enabled at the moment but I could work this out with my devops although he is kinda busy at the moment. If you think that this memory pattern is abnormal and not linked to a misconfiguration, we will try to set up it

[derekcollison]

You can use the NATS cli to also grab the profiles.

[derekcollison]

#4969

[derekcollison]

I tracked what I believe to be the issue down.. PR above fixes.

[david-wakeo]

Wow thanks for such a quick fix.

Just a quick question/remark. From the description, it seems you are implying that the problem only occurs after a reboot or inactivity. From what we can see through, the memory reaches maximum on each call (unless you define inactivity by 5 minutes without trying to do a similar message replay)

[derekcollison]

This has been merged to main, so be good to have you test it.

The linear walk could be cheaper if the walk happened within a sync interval of a msg block, which by default is 2m. The block cache of data expires fairly quickly but the subject indexing info per block, called fss, will linger up to the sync window if their is no activity in the block itself.

[david-wakeo]

Alright thanks for the explanation and for the quick fix

I'll test it whenever it's part of a released version and I'll report the results here

[derekcollison]

Be better to test against a nightly prior. You can grab the next nightly (will be built tonight or I could kick it). Run as a single server, restore a snapshot of the stream in question and have NATS cli create a consumer that shows the issue and check memory etc.

[david-wakeo]

Alright, makes sense

While waiting for the nightly, I'll first try to reproduce it locally with the current version

[david-wakeo]

Hello, I tested the latest changes with the following protocol:

• restore the stream (I assume the server version should not matter)
• stop the nats server
• start a nats docker image with last release (nats:2.9.10)
• request with nats cli (nats stream view) a subset of messages which are all toward the end of the stream
• check the memory when it stabilizes with docker stats
• stop the nats server
• redo the same with image with last nightly release (nats:nightly)

And here are the results:

• 2.10.9: timeout before any message could be retrieved, peak memory usage is +3.1GiB
• nightly: first message is resolved immediately, peak memory usage is +1.8GiB

So it looks like definitely better than before both latency wise and memory wise. There is still a large memory spike though but it may be normal?

Details:

MEMORY
========
Nighlty - Before
CONTAINER ID   NAME                     CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O        PIDS
d27b0968ef98   condescending_williams   0.12%     160.1MiB / 15.43GiB   1.01%     19.3kB / 29.1kB   3.25GB / 125MB   13

Nighlty - After
CONTAINER ID   NAME                     CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O        PIDS
d27b0968ef98   condescending_williams   0.07%     1.913GiB / 15.43GiB   12.40%    25.8kB / 58.3kB   4.76GB / 142MB   13

2.10.9 - Before
CONTAINER ID   NAME              CPU %     MEM USAGE / LIMIT     MEM %     NET I/O       BLOCK I/O         PIDS
1d153077ed15   wizardly_curran   0.13%     129.1MiB / 15.43GiB   0.82%     6.14kB / 0B   9.36MB / 48.5MB   13

2.10.9 - After
CONTAINER ID   NAME              CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O        PIDS
1d153077ed15   wizardly_curran   0.40%     3.273GiB / 15.43GiB   21.21%    9.52kB / 3.78kB   22.2GB / 164MB   14

[derekcollison]

I think we should be good with 2.10.11 release which happened yesterday. Feel free to close.