Summary

The user rpiotrow is experiencing unexpected execution times while executing parallel requests to a PostgreSQL database using the Effect Typescript library. The user has implemented a test with multiple sequential pg_sleep(5) SQL commands to simulate long transactions, running 20 parallel requests. When these commands are wrapped within a transaction, the execution time is consistently around 30 seconds, which aligns with the expected limit of 10 concurrent database connections. However, without transactions, the first run takes about 1 minute and 15 seconds, and subsequent runs take around 30 seconds each.

nikelborm has suggested using OpenTelemetry for better observability and presented a simplified version of the issue in different code, demonstrating the execution timing anomaly without requiring the exact previous setup. Both users express confusion over this behavior and seek understanding or solutions.

Key Takeaways:

Wrapping SQL commands in a transaction seems to stabilize execution times despite database connection limitations.
Without transactions, there are unexpectedly longer execution times initially, potentially due to connection handling specifics.
Instrumentation tools like OpenTelemetry can provide more insights into such performance issues.
The problem is reproducible with a simplified version of the code, facilitating further investigation and testing.

Discord thread

https://discord.com/channels/795981131316985866/1365319950763299028

Apr 25 '25 18:04 effect-bot

TLDR: It's an upstream issue: porsager/postgres#747

How to reproduce

Create main.ts

import { SqlClient } from "@effect/sql";
import { PgClient } from "@effect/sql-pg";
import { Console, Duration, Effect, Redacted, pipe } from "effect";

const SqlLive = PgClient.layer({
  username: "root",
  password: Redacted.make("mypass"),
  host: "localhost",
  port: 5432,
  database: "main",
  maxConnections: 10,
});

const test = Effect.gen(function* () {
  const sql = yield* SqlClient.SqlClient;
  const amount = 20;

  yield* Effect.all(
    Array.from({ length: amount }, (_, i) => {
      const task = `task #${i.toString(amount)}`;
      const startedAt = new Date();
      const time = () =>
        (
          Math.floor(
            Duration.toSeconds(Duration.millis(+new Date() - +startedAt))
          ) + "s"
        ).padStart(3, " ");

      return pipe(
        Console.log(`${task}   -> 1 at ${time()}`),
        Effect.flatMap(() => sql`select pg_sleep(5);`),
        Effect.flatMap(() => Console.log(`${task} 1 -> 2 at ${time()}`)),
        Effect.flatMap(() => sql`select pg_sleep(5);`),
        Effect.flatMap(() => Console.log(`${task} 2 -> 3 at ${time()}`)),
        Effect.flatMap(() => sql`select pg_sleep(5);`),
        Effect.flatMap(() => Console.log(`${task} 3 ->   at ${time()}`)),
        sql.withTransaction,
        Effect.map(() => undefined)
      );
    }),
    { concurrency: "unbounded" }
  );
});

pipe(
  test,
  Effect.provide(SqlLive),
  Effect.catchAll((e) => Console.error(e)),
  Effect.runFork
);

Create package.json

{
  "name": "fake-long-transactions",
  "version": "1.0.0",
  "type": "module",
  "description": "",
  "scripts": {
    "start": "node main.ts"
  },
  "keywords": [],
  "author": "",

  "dependencies": {
    "effect": "^3.14.14",
    "@effect/sql": "^0.33.14",
    "@effect/sql-pg": "^0.34.14",
    "typescript": "^5.8.3"
  }
}

Install dependencies:
```
npm i
```

Create PostgreSQL docker container:

docker run --name postgresql-testdb -p 5432:5432 -d -e POSTGRES_USER=root -e POSTGRES_PASSWORD=mypass postgres;
sleep 5;
echo "CREATE DATABASE main;" | docker exec -i postgresql-testdb psql;

Run the script (requires latest node)
```
npm start
```

See expected results with uncommented sql.withTransaction, which takes 30 seconds:

(Expandable) Logs: `yield* Effect.all(...)` takes 30 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #0 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #5 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #0 2 -> 3 at 10s
task #1 2 -> 3 at 10s
task #2 2 -> 3 at 10s
task #3 2 -> 3 at 10s
task #4 2 -> 3 at 10s
task #8 2 -> 3 at 10s
task #5 2 -> 3 at 10s
task #7 2 -> 3 at 10s
task #6 2 -> 3 at 10s
task #9 2 -> 3 at 10s
task #0 3 ->   at 15s
task #a   -> 1 at  0s
task #3 3 ->   at 15s
task #1 3 ->   at 15s
task #b   -> 1 at  0s
task #2 3 ->   at 15s
task #c   -> 1 at  0s
task #4 3 ->   at 15s
task #9 3 ->   at 15s
task #d   -> 1 at  0s
task #8 3 ->   at 15s
task #5 3 ->   at 15s
task #7 3 ->   at 15s
task #6 3 ->   at 15s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #j   -> 1 at  0s
task #i   -> 1 at  0s
task #a 1 -> 2 at 20s
task #b 1 -> 2 at 20s
task #c 1 -> 2 at 20s
task #d 1 -> 2 at 20s
task #f 1 -> 2 at 20s
task #e 1 -> 2 at 20s
task #g 1 -> 2 at 20s
task #h 1 -> 2 at 20s
task #j 1 -> 2 at 20s
task #i 1 -> 2 at 20s
task #a 2 -> 3 at 25s
task #b 2 -> 3 at 25s
task #c 2 -> 3 at 25s
task #d 2 -> 3 at 25s
task #f 2 -> 3 at 25s
task #e 2 -> 3 at 25s
task #g 2 -> 3 at 25s
task #h 2 -> 3 at 25s
task #j 2 -> 3 at 25s
task #i 2 -> 3 at 25s
task #a 3 ->   at 30s
task #b 3 ->   at 30s
task #d 3 ->   at 30s
task #c 3 ->   at 30s
task #f 3 ->   at 30s
task #g 3 ->   at 30s
task #e 3 ->   at 30s
task #h 3 ->   at 30s
task #j 3 ->   at 30s
task #i 3 ->   at 30s

The chart below represents the logs above:

0 -|x|x|x| | | |
1 -|x|x|x| | | |
2 -|x|x|x| | | |
3 -|x|x|x| | | |
4 -|x|x|x| | | |
5 -|x|x|x| | | |
6 -|x|x|x| | | |
7 -|x|x|x| | | |
8 -|x|x|x| | | |
9 -|x|x|x| | | |
a -| | | |x|x|x|
b -| | | |x|x|x|
c -| | | |x|x|x|
d -| | | |x|x|x|
e -| | | |x|x|x|
f -| | | |x|x|x|
g -| | | |x|x|x|
h -| | | |x|x|x|
i -| | | |x|x|x|
j -| | | |x|x|x|
   0 | 10| 20| 30
     5   15  25

Comment sql.withTransaction,
Run the script again

See unexpected results:

(Expandable) Logs: `yield* Effect.all(...)` takes 75 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #0 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #5 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #a 1 -> 2 at 10s
task #2 2 -> 3 at 10s
task #1 2 -> 3 at 10s
task #3 2 -> 3 at 10s
task #5 2 -> 3 at 10s
task #8 2 -> 3 at 10s
task #4 2 -> 3 at 10s
task #6 2 -> 3 at 10s
task #7 2 -> 3 at 10s
task #9 2 -> 3 at 10s
task #b 1 -> 2 at 15s
task #2 3 ->   at 15s
task #1 3 ->   at 15s
task #3 3 ->   at 15s
task #5 3 ->   at 15s
task #8 3 ->   at 15s
task #7 3 ->   at 15s
task #6 3 ->   at 15s
task #9 3 ->   at 15s
task #4 3 ->   at 15s
task #c 1 -> 2 at 20s
task #d 1 -> 2 at 25s
task #c 2 -> 3 at 25s
task #e 1 -> 2 at 30s
task #d 2 -> 3 at 30s
task #c 3 ->   at 30s
task #f 1 -> 2 at 35s
task #e 2 -> 3 at 35s
task #d 3 ->   at 35s
task #g 1 -> 2 at 40s
task #f 2 -> 3 at 40s
task #e 3 ->   at 40s
task #h 1 -> 2 at 45s
task #g 2 -> 3 at 45s
task #f 3 ->   at 45s
task #i 1 -> 2 at 50s
task #h 2 -> 3 at 50s
task #g 3 ->   at 50s
task #j 1 -> 2 at 55s
task #i 2 -> 3 at 55s
task #h 3 ->   at 55s
task #0 2 -> 3 at 60s
task #j 2 -> 3 at 60s
task #i 3 ->   at 60s
task #a 2 -> 3 at 65s
task #0 3 ->   at 65s
task #j 3 ->   at 65s
task #b 2 -> 3 at 70s
task #a 3 ->   at 70s
task #b 3 ->   at 75s

The chart below represents the logs above:

0 -|x| | | | | | | | | | |x|x| | |
1 -|x|x|x| | | | | | | | | | | | |
2 -|x|x|x| | | | | | | | | | | | |
3 -|x|x|x| | | | | | | | | | | | |
4 -|x|x|x| | | | | | | | | | | | |
5 -|x|x|x| | | | | | | | | | | | |
6 -|x|x|x| | | | | | | | | | | | |
7 -|x|x|x| | | | | | | | | | | | |
8 -|x|x|x| | | | | | | | | | | | |
9 -|x|x|x| | | | | | | | | | | | |
a -| |x| | | | | | | | | | |x|x| |
b -| | |x| | | | | | | | | | |x|x|
c -| | | |x|x|x| | | | | | | | | |
d -| | | | |x|x|x| | | | | | | | |
e -| | | | | |x|x|x| | | | | | | |
f -| | | | | | |x|x|x| | | | | | |
g -| | | | | | | |x|x|x| | | | | |
h -| | | | | | | | |x|x|x| | | | |
i -| | | | | | | | | |x|x|x| | | |
j -| | | | | | | | | | |x|x|x| | |
   0 | 10| 20| 30| 40| 50| 60| 70|
     5   15  25  35  45  55  65  75

As you may notice after the 15-second mark, no more than 3 connections at a time are active, which is unexpected.

Apr 25 '25 18:04 nikelborm

The strangest thing is that you can literally under the same process run the same effect twice, and it will initially take 1 minute 15 seconds and then take 30 seconds:

import { SqlClient } from "@effect/sql";
import { PgClient } from "@effect/sql-pg";
import { Console, Duration, Effect, Redacted, pipe } from "effect";

const SqlLive = PgClient.layer({
  username: "root",
  password: Redacted.make("mypass"),
  host: "localhost",
  port: 5432,
  database: "main",
  maxConnections: 10,
});

const test = Effect.gen(function* () {
  const sql = yield* SqlClient.SqlClient;
  const amount = 20;

  const effect = () =>
    Effect.all(
      Array.from({ length: amount }, (_, i) => {
        const task = `task #${i.toString(amount)}`;
        const startedAt = new Date();
        const time = () =>
          (
            Math.floor(
              Duration.toSeconds(Duration.millis(+new Date() - +startedAt))
            ) + "s"
          ).padStart(3, " ");

        return pipe(
          Console.log(`${task}   -> 1 at ${time()}`),
          Effect.flatMap(() => sql`select pg_sleep(5);`),
          Effect.flatMap(() => Console.log(`${task} 1 -> 2 at ${time()}`)),
          Effect.flatMap(() => sql`select pg_sleep(5);`),
          Effect.flatMap(() => Console.log(`${task} 2 -> 3 at ${time()}`)),
          Effect.flatMap(() => sql`select pg_sleep(5);`),
          Effect.flatMap(() => Console.log(`${task} 3 ->   at ${time()}`)),
          // sql.withTransaction,
          Effect.map(() => undefined)
        );
      }),
      { concurrency: "unbounded" }
    );

  yield* effect();

  yield* Console.log("\nThe f***ing magic\n");

  yield* effect();
});

pipe(
  test,
  Effect.provide(SqlLive),
  Effect.catchAll((e) => Console.error(e)),
  Effect.runFork
);

(Expandable) Logs: the first `yield* effect()` takes 75 seconds, the second takes 30 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #0 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #5 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #a 1 -> 2 at 10s
task #1 2 -> 3 at 10s
task #2 2 -> 3 at 10s
task #3 2 -> 3 at 10s
task #9 2 -> 3 at 10s
task #8 2 -> 3 at 10s
task #6 2 -> 3 at 10s
task #5 2 -> 3 at 10s
task #4 2 -> 3 at 10s
task #7 2 -> 3 at 10s
task #b 1 -> 2 at 15s
task #1 3 ->   at 15s
task #2 3 ->   at 15s
task #3 3 ->   at 15s
task #4 3 ->   at 15s
task #9 3 ->   at 15s
task #8 3 ->   at 15s
task #5 3 ->   at 15s
task #6 3 ->   at 15s
task #7 3 ->   at 15s
task #c 1 -> 2 at 20s
task #c 2 -> 3 at 25s
task #d 1 -> 2 at 25s
task #c 3 ->   at 30s
task #e 1 -> 2 at 30s
task #d 2 -> 3 at 30s
task #f 1 -> 2 at 35s
task #e 2 -> 3 at 35s
task #d 3 ->   at 35s
task #g 1 -> 2 at 40s
task #f 2 -> 3 at 40s
task #e 3 ->   at 40s
task #h 1 -> 2 at 45s
task #g 2 -> 3 at 45s
task #f 3 ->   at 45s
task #i 1 -> 2 at 50s
task #h 2 -> 3 at 50s
task #g 3 ->   at 50s
task #i 2 -> 3 at 55s
task #j 1 -> 2 at 55s
task #h 3 ->   at 55s
task #0 2 -> 3 at 60s
task #j 2 -> 3 at 60s
task #i 3 ->   at 60s
task #0 3 ->   at 65s
task #a 2 -> 3 at 65s
task #j 3 ->   at 65s
task #b 2 -> 3 at 70s
task #a 3 ->   at 70s
task #b 3 ->   at 75s

The f***ing magic

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #5 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #0 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #f 1 -> 2 at 10s
task #g 1 -> 2 at 10s
task #c 1 -> 2 at 10s
task #a 1 -> 2 at 10s
task #j 1 -> 2 at 10s
task #e 1 -> 2 at 10s
task #d 1 -> 2 at 10s
task #b 1 -> 2 at 10s
task #i 1 -> 2 at 10s
task #h 1 -> 2 at 10s
task #7 2 -> 3 at 15s
task #2 2 -> 3 at 15s
task #6 2 -> 3 at 15s
task #4 2 -> 3 at 15s
task #9 2 -> 3 at 15s
task #5 2 -> 3 at 15s
task #1 2 -> 3 at 15s
task #0 2 -> 3 at 15s
task #8 2 -> 3 at 15s
task #3 2 -> 3 at 15s
task #i 2 -> 3 at 20s
task #h 2 -> 3 at 20s
task #e 2 -> 3 at 20s
task #d 2 -> 3 at 20s
task #a 2 -> 3 at 20s
task #b 2 -> 3 at 20s
task #j 2 -> 3 at 20s
task #f 2 -> 3 at 20s
task #c 2 -> 3 at 20s
task #g 2 -> 3 at 20s
task #1 3 ->   at 25s
task #3 3 ->   at 25s
task #7 3 ->   at 25s
task #8 3 ->   at 25s
task #5 3 ->   at 25s
task #4 3 ->   at 25s
task #6 3 ->   at 25s
task #2 3 ->   at 25s
task #0 3 ->   at 25s
task #9 3 ->   at 25s
task #f 3 ->   at 30s
task #j 3 ->   at 30s
task #e 3 ->   at 30s
task #c 3 ->   at 30s
task #i 3 ->   at 30s
task #g 3 ->   at 30s
task #d 3 ->   at 30s
task #a 3 ->   at 30s
task #b 3 ->   at 30s
task #h 3 ->   at 30s

Apr 25 '25 19:04 nikelborm

CC @rpiotrow

Apr 25 '25 19:04 nikelborm

Also, it's unnecessary to run the script for 1 minute and 45 seconds together to reproduce the issue. The problem appears even on maxConnections: 2,, const amount = 4;, and 2 sequential SQL queries instead of 3

import { SqlClient } from "@effect/sql";
import { PgClient } from "@effect/sql-pg";
import { Console, Duration, Effect, Redacted, pipe } from "effect";

const SqlLive = PgClient.layer({
  username: "root",
  password: Redacted.make("mypass"),
  host: "localhost",
  port: 5432,
  database: "main",
  maxConnections: 2,
});

const test = Effect.gen(function* () {
  const sql = yield* SqlClient.SqlClient;
  const amount = 4;

  const effect = () =>
    Effect.all(
      Array.from({ length: amount }, (_, i) => {
        const task = `task #${i.toString(amount)}`;
        const startedAt = new Date();
        const time = () =>
          (
            Math.floor(
              Duration.toSeconds(Duration.millis(+new Date() - +startedAt))
            ) + "s"
          ).padStart(3, " ");

        return pipe(
          Console.log(`${task}   -> 1 at ${time()}`),
          Effect.flatMap(() => sql`select pg_sleep(5);`),
          Effect.flatMap(() => Console.log(`${task} 1 -> 2 at ${time()}`)),
          Effect.flatMap(() => sql`select pg_sleep(5);`),
          Effect.flatMap(() => Console.log(`${task} 2 ->   at ${time()}`)),
          // sql.withTransaction,
          Effect.map(() => undefined)
        );
      }),
      { concurrency: "unbounded" }
    );

  yield* effect();

  yield* Console.log("\nThe f***ing magic\n");

  yield* effect();
});

pipe(
  test,
  Effect.provide(SqlLive),
  Effect.catchAll((e) => Console.error(e)),
  Effect.runFork
);

(Expandable) Logs: the first `yield* effect()` takes 25 seconds, the second takes 20 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #0 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #2 1 -> 2 at 10s
task #1 2 ->   at 10s
task #3 1 -> 2 at 15s
task #0 2 ->   at 20s
task #3 2 ->   at 20s
task #2 2 ->   at 25s

The f***ing magic

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #1 1 -> 2 at  5s
task #0 1 -> 2 at  5s
task #3 1 -> 2 at 10s
task #2 1 -> 2 at 10s
task #1 2 ->   at 15s
task #0 2 ->   at 15s
task #3 2 ->   at 20s
task #2 2 ->   at 20s

Apr 25 '25 19:04 nikelborm

I think it's the issue inside postgres NPM package used as a dependency of @effect/sql-pg.

I just ran a simple script:

import postgres from "postgres";

const sql = postgres({
  user: "root",
  password: "mypass",
  host: "localhost",
  port: 5432,
  database: "main",
  idle_timeout: 3 * 60, // 3 minutes just in case -- more than enough
  connect_timeout: 3 * 60, // 3 minutes just in case -- more than enough
  max_lifetime: 30 * 60, //  30 minutes -- more than enough
  keep_alive: 3 * 60, // 3 minutes just in case -- more than enough
  max: 10,
});

await Promise.all(
  Array.from({ length: 20 }, async (_, i) => {
    const task = `task #${i.toString(20)}`;
    const startedAt = new Date();
    const time = () =>
      (
        Math.floor((new Date().getTime() - startedAt.getTime()) / 1000) + "s"
      ).padStart(3, " ");

    console.log(`${task}   -> 1 at ${time()}`);
    await sql`select pg_sleep(5);`;
    console.log(`${task} 1 -> 2 at ${time()}`);
    await sql`select pg_sleep(5);`;
    console.log(`${task} 2 -> 3 at ${time()}`);
    await sql`select pg_sleep(5);`;
    console.log(`${task} 3 ->   at ${time()}`);
  })
);

await sql.end();

The problem with it is that it started unloading connections too early, and so this version of the script took 40 seconds instead of the expected 30:

(Expandable) Logs: `await Promise.all(...)` takes 40 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #5 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #0 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #a 1 -> 2 at 10s
task #b 1 -> 2 at 10s
task #c 1 -> 2 at 10s
task #d 1 -> 2 at 10s
task #e 1 -> 2 at 10s
task #f 1 -> 2 at 10s
task #g 1 -> 2 at 10s
task #j 1 -> 2 at 10s
task #h 1 -> 2 at 10s
task #i 1 -> 2 at 10s
task #5 2 -> 3 at 15s
task #1 2 -> 3 at 15s
task #g 2 -> 3 at 15s
task #2 2 -> 3 at 15s
task #4 2 -> 3 at 15s
task #e 2 -> 3 at 15s
task #a 2 -> 3 at 15s
task #9 2 -> 3 at 15s
task #c 2 -> 3 at 15s
task #j 2 -> 3 at 15s
task #5 3 ->   at 20s
task #3 2 -> 3 at 20s
task #d 2 -> 3 at 20s
task #7 2 -> 3 at 20s
task #2 3 ->   at 20s
task #8 2 -> 3 at 20s
task #h 2 -> 3 at 20s
task #9 3 ->   at 20s
task #e 3 ->   at 20s
task #g 3 ->   at 20s
task #0 2 -> 3 at 25s
task #3 3 ->   at 25s
task #4 3 ->   at 25s
task #b 2 -> 3 at 25s
task #i 2 -> 3 at 25s
task #c 3 ->   at 25s
task #8 3 ->   at 25s
task #7 3 ->   at 25s
task #6 2 -> 3 at 30s
task #h 3 ->   at 30s
task #0 3 ->   at 30s
task #i 3 ->   at 30s
task #j 3 ->   at 30s
task #1 3 ->   at 30s
task #b 3 ->   at 30s
task #d 3 ->   at 35s
task #f 2 -> 3 at 35s
task #6 3 ->   at 35s
task #a 3 ->   at 40s
task #f 3 ->   at 40s

Here is a diagram representing logs from above:

0 -|x| | | |x|x| | |
1 -|x| |x| | |x| | |
2 -|x| |x|x| | | | |
3 -|x| | |x|x| | | |
4 -|x| |x| |x| | | |
5 -|x| |x|x| | | | |
6 -|x| | | | |x|x| |
7 -|x| | |x|x| | | |
8 -|x| | |x|x| | | |
9 -|x| |x|x| | | | |
a -| |x|x| | | | |x|
b -| |x| | |x|x| | |
c -| |x|x| |x| | | |
d -| |x| |x| | |x| |
e -| |x|x|x| | | | |
f -| |x| | | | |x|x|
g -| |x|x|x| | | | |
h -| |x| |x| |x| | |
i -| |x| | |x|x| | |
j -| |x|x| | |x| | |
   0 | 10| 20| 30| 40
     5   15  25  35

Notice that at the 25-second mark, there are already only 8 out of 10 connections being used. At 30 seconds, it's 7 connections. At 35 seconds, there are only 3 connections that weren't unloaded, etc

Apr 25 '25 22:04 nikelborm

I hypothesized that those connections just start being garbage collected, and that's it

But that doesn't make sense if we look at previous examples where the same code starts working fine, after running it again, and even faster than it was the first time.

The new script, where an identical situation to effects replicated with promises: The first promise run is bad and initially gives a bad speed result, and then starts working as expected during the second run:

import postgres from "postgres";

const sql = postgres({
  user: "root",
  password: "mypass",
  host: "localhost",
  port: 5432,
  database: "main",
  idle_timeout: 5 * 60, // 5 minutes just in case
  connect_timeout: 5 * 60, // 5 minutes just in case
  max_lifetime: 30 * 60,
  keep_alive: 5 * 60, // 5 minutes just in case
  max: 10,
});

const test = () =>
  Promise.all(
    Array.from({ length: 20 }, async (_, i) => {
      const task = `task #${i.toString(20)}`;
      const startedAt = new Date();
      const time = () =>
        (
          Math.floor((new Date().getTime() - startedAt.getTime()) / 1000) + "s"
        ).padStart(3, " ");

      console.log(`${task}   -> 1 at ${time()}`);
      await sql`select pg_sleep(5);`;
      console.log(`${task} 1 -> 2 at ${time()}`);
      await sql`select pg_sleep(5);`;
      console.log(`${task} 2 -> 3 at ${time()}`);
      await sql`select pg_sleep(5);`;
      console.log(`${task} 3 ->   at ${time()}`);
    })
  );

await test();

console.log("\nThe f***ing magic\n");

await test();

await sql.end();

(Expandable) Logs: the first `await test()` takes 40 seconds, the second takes 30 seconds

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #1 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #0 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #5 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #a 1 -> 2 at 10s
task #b 1 -> 2 at 10s
task #f 1 -> 2 at 10s
task #c 1 -> 2 at 10s
task #d 1 -> 2 at 10s
task #g 1 -> 2 at 10s
task #e 1 -> 2 at 10s
task #h 1 -> 2 at 10s
task #i 1 -> 2 at 10s
task #j 1 -> 2 at 10s
task #1 2 -> 3 at 15s
task #0 2 -> 3 at 15s
task #2 2 -> 3 at 15s
task #8 2 -> 3 at 15s
task #f 2 -> 3 at 15s
task #a 2 -> 3 at 15s
task #5 2 -> 3 at 15s
task #d 2 -> 3 at 15s
task #e 2 -> 3 at 15s
task #i 2 -> 3 at 15s
task #4 2 -> 3 at 20s
task #6 2 -> 3 at 20s
task #c 2 -> 3 at 20s
task #1 3 ->   at 20s
task #2 3 ->   at 20s
task #9 2 -> 3 at 20s
task #h 2 -> 3 at 20s
task #e 3 ->   at 20s
task #5 3 ->   at 20s
task #f 3 ->   at 20s
task #3 2 -> 3 at 25s
task #b 2 -> 3 at 25s
task #8 3 ->   at 25s
task #4 3 ->   at 25s
task #c 3 ->   at 25s
task #j 2 -> 3 at 25s
task #h 3 ->   at 25s
task #d 3 ->   at 25s
task #7 2 -> 3 at 30s
task #3 3 ->   at 30s
task #b 3 ->   at 30s
task #0 3 ->   at 30s
task #9 3 ->   at 30s
task #i 3 ->   at 30s
task #j 3 ->   at 30s
task #7 3 ->   at 35s
task #g 2 -> 3 at 35s
task #6 3 ->   at 35s
task #g 3 ->   at 40s
task #a 3 ->   at 40s

The f***ing magic

task #0   -> 1 at  0s
task #1   -> 1 at  0s
task #2   -> 1 at  0s
task #3   -> 1 at  0s
task #4   -> 1 at  0s
task #5   -> 1 at  0s
task #6   -> 1 at  0s
task #7   -> 1 at  0s
task #8   -> 1 at  0s
task #9   -> 1 at  0s
task #a   -> 1 at  0s
task #b   -> 1 at  0s
task #c   -> 1 at  0s
task #d   -> 1 at  0s
task #e   -> 1 at  0s
task #f   -> 1 at  0s
task #g   -> 1 at  0s
task #h   -> 1 at  0s
task #i   -> 1 at  0s
task #j   -> 1 at  0s
task #0 1 -> 2 at  5s
task #3 1 -> 2 at  5s
task #5 1 -> 2 at  5s
task #7 1 -> 2 at  5s
task #2 1 -> 2 at  5s
task #8 1 -> 2 at  5s
task #1 1 -> 2 at  5s
task #4 1 -> 2 at  5s
task #6 1 -> 2 at  5s
task #9 1 -> 2 at  5s
task #a 1 -> 2 at 10s
task #c 1 -> 2 at 10s
task #d 1 -> 2 at 10s
task #h 1 -> 2 at 10s
task #e 1 -> 2 at 10s
task #f 1 -> 2 at 10s
task #b 1 -> 2 at 10s
task #i 1 -> 2 at 10s
task #g 1 -> 2 at 10s
task #j 1 -> 2 at 10s
task #3 2 -> 3 at 15s
task #7 2 -> 3 at 15s
task #5 2 -> 3 at 15s
task #2 2 -> 3 at 15s
task #4 2 -> 3 at 15s
task #0 2 -> 3 at 15s
task #8 2 -> 3 at 15s
task #9 2 -> 3 at 15s
task #6 2 -> 3 at 15s
task #1 2 -> 3 at 15s
task #a 2 -> 3 at 20s
task #h 2 -> 3 at 20s
task #e 2 -> 3 at 20s
task #g 2 -> 3 at 20s
task #i 2 -> 3 at 20s
task #f 2 -> 3 at 20s
task #d 2 -> 3 at 20s
task #j 2 -> 3 at 20s
task #c 2 -> 3 at 20s
task #b 2 -> 3 at 20s
task #2 3 ->   at 25s
task #1 3 ->   at 25s
task #3 3 ->   at 25s
task #0 3 ->   at 25s
task #9 3 ->   at 25s
task #5 3 ->   at 25s
task #6 3 ->   at 25s
task #7 3 ->   at 25s
task #4 3 ->   at 25s
task #8 3 ->   at 25s
task #g 3 ->   at 30s
task #b 3 ->   at 30s
task #a 3 ->   at 30s
task #f 3 ->   at 30s
task #c 3 ->   at 30s
task #e 3 ->   at 30s
task #j 3 ->   at 30s
task #h 3 ->   at 30s
task #i 3 ->   at 30s
task #d 3 ->   at 30s

The diagram of the first await test() is identical to the one in this comment.

Here is the diagram of the second await test():

0 -|x| |x| |x| |
1 -|x| |x| |x| |
2 -|x| |x| |x| |
3 -|x| |x| |x| |
4 -|x| |x| |x| |
5 -|x| |x| |x| |
6 -|x| |x| |x| |
7 -|x| |x| |x| |
8 -|x| |x| |x| |
9 -|x| |x| |x| |
a -| |x| |x| |x|
b -| |x| |x| |x|
c -| |x| |x| |x|
d -| |x| |x| |x|
e -| |x| |x| |x|
f -| |x| |x| |x|
g -| |x| |x| |x|
h -| |x| |x| |x|
i -| |x| |x| |x|
j -| |x| |x| |x|
   0 | 10| 20| 30
     5   15  25

Apr 25 '25 23:04 nikelborm

I think I know the root of the issue. I guess it can be called "an upstream issue", which you can find here

As the author of the library said:

I've looked closer, and there's a really bad regression all the way back from 3.0.1. I'll be looking deeper into this tomorrow.

The issue dates back to release v3.0.1, which unfortunately was more than 3 years ago (Mar 30, 2022)

Sadly, even when I tried to roll back to v3.0.0, nothing changed, so I assume it was never stable

PS. I wouldn't mind rewriting it to pg library myself, if you let me. I think it would be a great learning opportunity for me, and just fun

Apr 26 '25 01:04 nikelborm

The issue have to be closed probably, since postgres.js is not used anymore

https://github.com/Effect-TS/effect/pull/5646/files#diff-3e92112780a70ba56d16b5dccce1bbc530a0c63433832f7e194d24eb4aabd33b

Nov 04 '25 15:11 nikelborm

From Discord: Unexpected Execution Time with Parallel Requests and Database Transactions

Summary

Discord thread

TLDR: It's an upstream issue: porsager/postgres#747

How to reproduce