prisma: When executing queries in parallel, each next connection to the database gets progressively slower

Bug description

In investigating some latency issues we have been experiencing, we have found that attempting multiple concurrent async queries at once exhibits behavior closer to serial queries even when increasing our connection pool limit, i.e. queries are remaining queued waiting for a connection for much longer than we expect regardless of connection pool limit.

How to reproduce

1. Run the following script:

import { PrismaClient, WriteSmall } from "@prisma/client";
import { v4 as uuid } from "uuid";

type RandData = Omit<WriteSmall, "rowId" | "id">;

const getData = (n: number): [string, RandData][] => {
  const data = [];
  const rowIds = [];
  for (let i = 0; i < n; i++) {
    rowIds.push(uuid());
  }
  for (let i = 0; i < n; i++) {
    const randVal = Math.floor(Math.random() * 100);
    data.push([
      rowIds[i],
      { name: `name_${randVal}`, status: randVal % 2 === 0, count: randVal },
    ]);
  }
  return data;
};

const prismaCreate = (rowId: string, randData: RandData) => {
  return client.writeSmall.create({ data: { rowId, ...randData } });
};

const createConcurrently = async () => {
  const NUM_WRITES = 100;
  const promises = [];
  const durations = [];
  const startTimes = Array(NUM_WRITES);
  const data = getData(NUM_WRITES);
  for (let i = 0; i < NUM_WRITES; i++) {
    const [rowId, randData] = data[i];
    startTimes[i] = Date.now();
    promises.push(
      prismaCreate(rowId, randData)
        .then(() => {
          const now = Date.now();
          const duration = now - startTimes[i];
          durations.push(duration);
          console.log(
            `Finished create ${i} at ${now} in ${duration} with start time ${startTimes[i]}`
          );
        })
        .catch((e) => console.log(e))
    );
  }
  let allSettled = await Promise.allSettled(promises);
  const avgTime = durations.reduce((acc, curr) => curr + acc, 0) / durations.length;;
  const failures = allSettled.filter(
    (val) => val.status !== "fulfilled"
  ).length;
  console.log(
    `Finished with an average time of ${avgTime} ms with ${failures} failures`
  );
};

main()
  .then(() => console.log("Done"))
  .catch((e) => console.log(e));

1. Watch output as later writes experience significant lag waiting for previous writes to complete.
2. Adjust connection_limit to a higher value.
3. Watch output and see that later writes are still experiencing significant lag.

Click to see example logs

Finished create 0 at 1651608806235 in 3101 with start time 1651608803134
Finished create 1 at 1651608807848 in 4707 with start time 1651608803141
Finished create 2 at 1651608808988 in 5847 with start time 1651608803141
Finished create 4 at 1651608809418 in 6276 with start time 1651608803142
Finished create 7 at 1651608810617 in 7474 with start time 1651608803143
Finished create 5 at 1651608810632 in 7490 with start time 1651608803142
Finished create 3 at 1651608811126 in 7984 with start time 1651608803142
Finished create 8 at 1651608812267 in 9124 with start time 1651608803143
Finished create 9 at 1651608812284 in 9141 with start time 1651608803143
Finished create 10 at 1651608812298 in 9155 with start time 1651608803143
Finished create 6 at 1651608812767 in 9625 with start time 1651608803142
Finished create 12 at 1651608813861 in 10717 with start time 1651608803144
Finished create 14 at 1651608813874 in 10730 with start time 1651608803144
Finished create 13 at 1651608813893 in 10749 with start time 1651608803144
Finished create 15 at 1651608813894 in 10750 with start time 1651608803144
Finished create 11 at 1651608814315 in 11172 with start time 1651608803143
Finished create 17 at 1651608815506 in 12359 with start time 1651608803147
Finished create 21 at 1651608815506 in 12358 with start time 1651608803148
Finished create 16 at 1651608815511 in 12367 with start time 1651608803144
Finished create 19 at 1651608815527 in 12380 with start time 1651608803147
Finished create 20 at 1651608815531 in 12384 with start time 1651608803147
Finished create 18 at 1651608815980 in 12833 with start time 1651608803147
Finished create 23 at 1651608817145 in 13997 with start time 1651608803148
Finished create 24 at 1651608817145 in 13997 with start time 1651608803148
Finished create 25 at 1651608817155 in 14007 with start time 1651608803148
Finished create 28 at 1651608817164 in 14015 with start time 1651608803149
Finished create 26 at 1651608817173 in 14025 with start time 1651608803148
Finished create 27 at 1651608817173 in 14025 with start time 1651608803148
Finished create 22 at 1651608817640 in 14492 with start time 1651608803148
Finished create 30 at 1651608818791 in 15642 with start time 1651608803149
Finished create 31 at 1651608818795 in 15646 with start time 1651608803149
Finished create 32 at 1651608818801 in 15652 with start time 1651608803149
Finished create 33 at 1651608818811 in 15662 with start time 1651608803149
Finished create 36 at 1651608818817 in 15667 with start time 1651608803150
Finished create 35 at 1651608818818 in 15668 with start time 1651608803150
...

Expected behavior

Up to a point (depending on the database’s connection load), the actions are able to run increasingly concurrently as connection pool limit is increased.

Prisma information

Schema:

datasource db {
    provider = "postgresql"
    url = "postgress://user:password@host:port/db?connection_limit=10"
}

model WriteSmall {
  id Int @id @default(autoincrement())
  rowId String @db.VarChar(255) @unique
  name String @db.VarChar(255)
  count Int
  status Boolean

  createdAt DateTime @default(now())
  updatedAt DateTime @updatedAt
}

generator client {
    provider = "prisma-client-js"
}

We are running the following query:

client.writeSmall.create({ data: { rowId, ...randData } })

Environment & setup

• OS: Ubuntu
• Database: PostgreSQL
• Node.js version: v14.17.6

Prisma Version

prisma                  : 3.13.0
@prisma/client          : 3.13.0
Current platform        : debian-openssl-1.1.x
Query Engine (Node-API) : libquery-engine efdf9b1183dddfd4258cd181a72125755215ab7b (at ../.npm/_npx/2778af9cee32ff87/node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node)
Migration Engine        : migration-engine-cli efdf9b1183dddfd4258cd181a72125755215ab7b (at ../.npm/_npx/2778af9cee32ff87/node_modules/@prisma/engines/migration-engine-debian-openssl-1.1.x)
Introspection Engine    : introspection-core efdf9b1183dddfd4258cd181a72125755215ab7b (at ../.npm/_npx/2778af9cee32ff87/node_modules/@prisma/engines/introspection-engine-debian-openssl-1.1.x)
Format Binary           : prisma-fmt efdf9b1183dddfd4258cd181a72125755215ab7b (at ../.npm/_npx/2778af9cee32ff87/node_modules/@prisma/engines/prisma-fmt-debian-openssl-1.1.x)
Default Engines Hash    : efdf9b1183dddfd4258cd181a72125755215ab7b
Studio                  : 0.459.0