Increasing in message delivery delay

[1995parham]

We had a consumer that consuming messages from a stream named rides. The consumer using new API which creates a pull-based consumer. I've attached the stream and consumer configuration:

Information for Stream rides created 2024-07-25 20:34:56

             Description: Ride related events
                Subjects: 
                Replicas: 3
                 Storage: File

Options:

               Retention: Limits
         Acknowledgments: true
          Discard Policy: Old
        Duplicate Window: 2m0s
       Allows Msg Delete: true
            Allows Purge: true
  Allows Per-Message TTL: false
          Allows Rollups: false

Limits:

        Maximum Messages: unlimited
     Maximum Per Subject: unlimited
           Maximum Bytes: 1.9 GiB
             Maximum Age: 1h0m0s
    Maximum Message Size: unlimited
       Maximum Consumers: unlimited

Cluster Information:

                    Name: js-nats-production
           Cluster Group: S-R3F-qtVXkc6T
                  Leader: js-nats-production-2
                 Replica: js-nats-production-1, current, seen 591µs ago
                 Replica: js-nats-production-4, current, seen 459µs ago

State:

                Messages: 2,732,375
                   Bytes: 1.9 GiB
          First Sequence: 9,231,933,467 @ 2025-04-23 13:30:14
           Last Sequence: 9,234,665,841 @ 2025-04-23 14:27:29
        Active Consumers: 68
      Number of Subjects: 30

Information for Consumer rides > golchin-teh1-okd4 created 2025-02-26T19:10:11Z

Configuration:

                    Name: golchin-teh1-okd4
               Pull Mode: true
         Filter Subjects: 
          Deliver Policy: New
              Ack Policy: Explicit
                Ack Wait: 30.00s
           Replay Policy: Instant
         Max Ack Pending: 512
       Max Waiting Pulls: 512
      Inactive Threshold: 1m0s

Cluster Information:

                    Name: js-nats-production
              Raft Group: C-R3F-qNwdksaj
                  Leader: js-nats-production-2
                 Replica: js-nats-production-1, current, seen 394ms ago
                 Replica: js-nats-production-4, current, seen 394ms ago

State:

  Last Delivered Message: Consumer sequence: 1,070,076,752 Stream sequence: 9,228,326,079 Last delivery: 12.83s ago
    Acknowledgment Floor: Consumer sequence: 1,070,076,752 Stream sequence: 9,228,326,079 Last Ack: 12.77s ago
        Outstanding Acks: 0 out of maximum 512
    Redelivered Messages: 0
    Unprocessed Messages: 0
           Waiting Pulls: 16 of maximum 512

They enabled a feature which caused increase in the processing time, but after disabling the feature they still experience high latency in reading from NATS which we also have it in their consumer state as I shared. After waiting for a while and make sure their processing time reduced, we do a leader change over consumer and it resolved the latency. Also, this remove their pending messages too.

[wallyqs]

Hi @1995parham, could you share the nats server version? It sounds like the consumer leader was reading from a replica that was continuously behind catching up. Using latest natscli you can try checking for possible conditions to repair on your stream using nats server stream-check --expected 5 --timeout 60s and nats server consumer-check --expected 5 --timeout 60s.

[1995parham]

Thanks for replying. Here is our server information:

                      Version: 2.10.21
                   Git Commit: d3a8868
                   Go Version: go1.22.7
                   Start Time: 2025-03-16 07:42:03
      Configuration Load Time: 2025-03-16 07:42:03
                       Uptime: 38d8h0m29s

We are planning to upgrade it in the near future. Besides that, thanks for sharing these new commands. The first consumer leader was js-nats-production-2 which is the stream leader and after changing the leader, it changed into js-nats-production-1 which surprisingly resolved our issue. Let me share these commands output:

Connected in 0.135s
Response took 0.131s
Servers: 5
Streams: 26
╭──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                                                                                                                                    Streams                                                                                                                                                   │
├────────────────┬────────────────┬─────────┬────────────┬───────────────────────┬──────────┬────────────┬──────────┬─────────┬───────────┬────────────┬────────────┬──────────┬──────────────────────┬─────────────────────────────────────────────────────────────────────────────────────────────────────┬──┤
│ Stream Replica │ Raft           │ Account │ Account ID │ Node                  │ Messages │      Bytes │ Subjects │ Deleted │ Consumers │      First │       Last │ Status   │ Leader               │ Peers                                                                                               │  │
├────────────────┼────────────────┼─────────┼────────────┼───────────────────────┼──────────┼────────────┼──────────┼─────────┼───────────┼────────────┼────────────┼──────────┼──────────────────────┼─────────────────────────────────────────────────────────────────────────────────────────────────────┼──┤
│ rides          │ S-R3F-qtVXkc6T │ $G      │ $G         │ js-nats-production-1  │  2697503 │ 1970997505 │       31 │       0 │        67 │ 9235520008 │ 9238217510 │ UNSYNCED │ js-nats-production-2 │ js-nats-production-4(current=false,offline=false) js-nats-production-2(current=true ,offline=false) │  │
│ rides          │ S-R3F-qtVXkc6T │ $G      │ $G         │ js-nats-production-2* │  2697279 │ 1970834026 │       31 │       0 │        67 │ 9235520233 │ 9238217511 │ UNSYNCED │ js-nats-production-2 │ js-nats-production-4(current=true ,offline=false) js-nats-production-1(current=true ,offline=false) │  │
│ rides          │ S-R3F-qtVXkc6T │ $G      │ $G         │ js-nats-production-4  │  2697101 │ 1970703870 │       31 │       0 │        68 │ 9235520410 │ 9238217510 │ UNSYNCED │ js-nats-production-2 │ js-nats-production-2(current=true ,offline=false) js-nats-production-1(current=false,offline=false) │  │
╰────────────────┴────────────────┴─────────┴────────────┴───────────────────────┴──────────┴────────────┴──────────┴─────────┴───────────┴────────────┴────────────┴──────────┴──────────────────────┴─────────────────────────────────────────────────────────────────────────────────────────────────────┴──╯

Connected in 0.509s
Response took 0.601s
Servers: 5
Consumers: 257
╭────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│                                                                                                                                                                                  Consumers                                                                                                                                                                                 │
├───────────────────┬────────┬────────────────┬─────────┬────────────┬───────────────────────┬───────────────────────────────────────────────────────┬─────────────────────────┬───────────────────────────┬─────────┬──────────────────────┬───────────────────────┬─────────────────────────────────────────────────────────────────────────────────────────────────────┬──┤
│ Consumer          │ Stream │ Raft           │ Account │ Account ID │ Node                  │ Delivered (S,C)                                       │ ACK Floor (S,C)         │ Counters                  │ Status  │ Leader               │ Stream Cluster Leader │ Peers                                                                                               │  │
├───────────────────┼────────┼────────────────┼─────────┼────────────┼───────────────────────┼───────────────────────────────────────────────────────┼─────────────────────────┼───────────────────────────┼─────────┼──────────────────────┼───────────────────────┼─────────────────────────────────────────────────────────────────────────────────────────────────────┼──┤
│ golchin-teh1-okd4 │ rides  │ C-R3F-qNwdksaj │ $G      │ $G         │ js-nats-production-1* │ 9238345044 [9235648595, 9238345045] 100% | 1076048232 │ 9238345042 | 1076048230 │ (ap:2, nr:0, nw:12, np:0) │ IN SYNC │ js-nats-production-1 │ js-nats-production-2  │ js-nats-production-4(current=true ,offline=false) js-nats-production-2(current=true ,offline=false) │  │
│ golchin-teh1-okd4 │ rides  │ C-R3F-qNwdksaj │ $G      │ $G         │ js-nats-production-2  │ 9238345044 [9235648078, 9238345045] 100% | 1076048232 │ 9238345042 | 1076048230 │ (ap:2, nr:0, nw:0, np:0)  │ IN SYNC │ js-nats-production-1 │ js-nats-production-2  │ js-nats-production-4(current=false,offline=false) js-nats-production-1(current=true ,offline=false) │  │
│ golchin-teh1-okd4 │ rides  │ C-R3F-qNwdksaj │ $G      │ $G         │ js-nats-production-4  │ 9238345044 [9235648250, 9238345045] 100% | 1076048232 │ 9238345042 | 1076048230 │ (ap:2, nr:0, nw:0, np:0)  │ IN SYNC │ js-nats-production-1 │ js-nats-production-2  │ js-nats-production-2(current=false,offline=false) js-nats-production-1(current=true ,offline=false) │  │
╰───────────────────┴────────┴────────────────┴─────────┴────────────┴───────────────────────┴───────────────────────────────────────────────────────┴─────────────────────────┴───────────────────────────┴─────────┴──────────────────────┴───────────────────────┴─────────────────────────────────────────────────────────────────────────────────────────────────────┴──╯

It would be awesome if you can point me where I can read about the information these commands share and how I can interpret them.

[1995parham]

@wallyqs sorry for mentioning, I just want to ask about these responses and the information they provide.