Deadline Exceeded error occurs for all the events after deadline limit passes

I have v22.10.2.0 of EventStoreDB:and v5.0.1 of @eventstore/db-client for nodejs is installed. Following is my code. The idea is to perform a load test by appending 1000 messages each second.

import { EventStoreDBClient } from "@eventstore/db-client";
import log from "node-file-logger";
import { jsonEvent } from "@eventstore/db-client";
import { v4 as uuid } from 'uuid';

const eventStoreClient = EventStoreDBClient.connectionString`esdb://localhost:2111,localhost:2112,localhost:2113?tls=false`;

const sendEvent = async function (event) {
  try {
    let sent = await eventStoreClient.appendToStream(event.stream, event.event);

    sent = {
      ...sent,
      nextExpectedRevision: sent.nextExpectedRevision.toString(),
      position: {
        commit: sent.position.commit.toString(),
        prepare: sent.position.prepare.toString()
      }
    }

    log.Info(sent)
    return 0;
  } catch (error) {
    log.Error("--------------------------------ERROR EVENT---------------------------------------");
    log.Error(event);
    log.Error(error);
    log.Error("----------------------------------------------------------------------------------");
    sendEvent(event);
    return 0;
  }
}

const payload = {
    // 5kb test payload
}

const generateTestEvent = () => {
  return {
    stream: "LoadTestStream",
    event: jsonEvent({
      type: "LoadTest",
      data: {
        entityId: uuid(),
        ...payload
      },
    })
  };
};

// Generate 1000 events per second
setInterval(function () {

  for (let i = 1; i <= 1000; i++) {
    const randomEvent = generateTestEvent();
    sendEvent(randomEvent);
  }

}, 1000);

When the execution is started, the code works fine and all event append successfully. But after the deaultDeadline limit passes, the code throws a deadline-exceeded exception. I tried overriding the defaultDeadline value but the behavior didn’t change. All events append successfully until the specified deadline passes and after that, the same deadline-exceeded exception is thrown for each event. I have the following questions:

  1. How can I set infinite deadline except specifying a very large integer as the deadline?
  2. As I am not appending event in batches. Shouldn’t the deadline reset after every append?
  3. Anything that I am missing and can be helpful to me.

Are there any errors / warning in the server logs ?
( particulary on the leader node at the time of appends )

No, I could not locate any error in the logs. I have attached the logs file of the leader node, in case it might be helpful

Thnks !
I’m assuming you’re running 3 nodes in docker. Correct ?

Yes, that is right. The three nodes cluster configuration provided in the official documentation

One more thing I want to mention is that my docker containers are in unhealthy state. Although I can access the UI just fine, and the events that append successfully are also readable from the UI and subscriptions.

@yves.lorphelin These messages appeared in the logs of leader node during the DeadlineExceeded error. After this I close the client program and terminated the connection

[    1,12,14:33:50.272,DBG] SLOW QUEUE MSG ["StorageWriterQueue"]: "WritePrepares" - 879ms. Q: 0/830. "WritePrepares CorrelationId: 70566512-c92e-46ce-9c7f-cfe4d6485492, EventStreamId: LoadTestStream, ExpectedVersion: -2, Envelope: { EventStore.Core.Messaging.PublishEnvelope }, NumEvents: 1, DataBytes: 4907, MetadataBytes: 0".
[    1,12,14:33:51.256,DBG] SLOW QUEUE MSG ["StorageWriterQueue"]: "WritePrepares" - 794ms. Q: 0/549. "WritePrepares CorrelationId: afeceadb-9a0f-4b0c-8c52-32e080f6138c, EventStreamId: LoadTestStream, ExpectedVersion: -2, Envelope: { EventStore.Core.Messaging.PublishEnvelope }, NumEvents: 1, DataBytes: 4907, MetadataBytes: 0".
[    1,26,14:33:51.996,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 56ms. Handler: "UnwrapEnvelopeHandler".
[    1,26,14:33:51.996,DBG] SLOW QUEUE MSG ["Projection Core #2"]: "UnwrapEnvelopeMessage" - 56ms. Q: 0/252. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,25,14:33:52.030,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 84ms. Handler: "UnwrapEnvelopeHandler".
[    1,25,14:33:52.030,DBG] SLOW QUEUE MSG ["Projection Core #1"]: "UnwrapEnvelopeMessage" - 84ms. Q: 0/252. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,25,14:33:52.111,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 63ms. Handler: "UnwrapEnvelopeHandler".
[    1,25,14:33:52.111,DBG] SLOW QUEUE MSG ["Projection Core #1"]: "UnwrapEnvelopeMessage" - 63ms. Q: 0/253. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,24,14:33:52.160,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 66ms. Handler: "UnwrapEnvelopeHandler".
[    1,24,14:33:52.161,DBG] SLOW QUEUE MSG ["Projection Core #0"]: "UnwrapEnvelopeMessage" - 66ms. Q: 0/253. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,26,14:33:52.166,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 70ms. Handler: "UnwrapEnvelopeHandler".
[    1,26,14:33:52.166,DBG] SLOW QUEUE MSG ["Projection Core #2"]: "UnwrapEnvelopeMessage" - 70ms. Q: 0/253. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,25,14:33:52.195,DBG] SLOW BUS MSG ["bus"]: "UnwrapEnvelopeMessage" - 84ms. Handler: "UnwrapEnvelopeHandler".
[    1,25,14:33:52.195,DBG] SLOW QUEUE MSG ["Projection Core #1"]: "UnwrapEnvelopeMessage" - 84ms. Q: 176/429. "EventStore.Projections.Core.Messaging.UnwrapEnvelopeMessage".
[    1,12,14:33:53.056,DBG] SLOW QUEUE MSG ["StorageWriterQueue"]: "WritePrepares" - 1538ms. Q: 0/413. "WritePrepares CorrelationId: 5a375c0b-5042-41f7-bb58-f3c458827fa6, EventStreamId: LoadTestStream, ExpectedVersion: -2, Envelope: { EventStore.Core.Messaging.PublishEnvelope }, NumEvents: 1, DataBytes: 4907, MetadataBytes: 0".
[    1,15,14:33:53.237,DBG] IDEMPOTENT WRITE TO STREAM ClientCorrelationID 7db221bb-11e3-418a-8f42-2fab5101b4a0, "EventStreamId: LoadTestStream, CorrelationId: a220c566-3e4a-41fc-b998-7ee4c2d89ff5, FirstEventNumber: 63024, LastEventNumber: 63024".
[    1,15,14:33:53.238,DBG] IDEMPOTENT WRITE TO STREAM ClientCorrelationID 824ebea6-bd79-4edb-a675-e076cdb6a09e, "EventStreamId: LoadTestStream, CorrelationId: 139c9016-43a5-48cc-83c2-939c3ad8b890, FirstEventNumber: 63023, LastEventNumber: 63023".

It looks like the storage is rather slow.

[ 1,12,14:33:53.056,DBG] SLOW QUEUE MSG [“StorageWriterQueue”]: “WritePrepares” - 1538ms. Q: 0/413. “WritePrepares CorrelationId: 5a375c0b-5042-41f7-bb58-f3c458827fa6, EventStreamId: LoadTestStream, ExpectedVersion: -2, Envelope: { EventStore.Core.Messaging.PublishEnvelope }, NumEvents: 1, DataBytes: 4907, MetadataBytes: 0”.

1.5 seconds to write ±5k to disk is quite a bit.