Slow `count()` query with Relation Filter PostgreSQL

Bug description

query count with relation getting slower after 5 times request, this issues persist with more than 400k++ rows data being counted

I manage to forcing disconnect client by calling await prisma.$disconnect() after calling query count to temporary fix this issue, but this method will decrease performance of prisma at all, since this function await prisma.$disconnect() will take some time to reconnect all of clients.

i have tried to using raw query, and transaction query but the issues still persist. i have tried to manually query with pgadmin4 to see its server related issues, but the query running well with pgadmin4

Notes: i have same method with different table (smaller rows data) and its working properly without forcing client to disconnect

How to reproduce

i have create some project to reproduce the issues you can clone from this repo https://github.com/BagasNS/prisma-reproduce-slow-query then follow readme

Expected behavior

query count not getting slow without disconnecting the client (calling await prisma.$disconnect())

Prisma information

// This is your Prisma schema file,
// learn more about it in the docs: https://pris.ly/d/prisma-schema

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

datasource db {
  provider = "postgresql"
  url      = env("DATABASE_URL")
}

model accounts {
  id_account        String           @id @default(uuid())
  full_name         String
  calon             calon?
  surveyor          surveyor?
  pemilih           pemilih?
}

model calon {
  id_calon                 String                     @id @default(uuid())
  id_account               String                     @unique
  account                  accounts                   @relation(fields: [id_account], references: [id_account])
  dukungan                 dukungan[]
}

model pemilih {
  id_pemilih        String            @id @default(uuid())
  id_account        String            @unique
  account           accounts          @relation(fields: [id_account], references: [id_account])
  dukungan          dukungan[]
}

model surveyor {
  id_surveyor        String           @id @default(uuid())
  id_account        String           @unique
  account           accounts         @relation(fields: [id_account], references: [id_account])
  dukungan          dukungan[]
}

model dukungan {
  id_dukungan    String     @id @default(uuid())
  id_pemilih     String
  pemilih        pemilih    @relation(fields: [id_pemilih], references: [id_pemilih])
  id_surveyor    String
  surveyor       surveyor    @relation(fields: [id_surveyor], references: [id_surveyor])
  level_dukungan LevelDukungan // enum
  id_calon       String
  calon          calon      @relation(fields: [id_calon], references: [id_calon])
  created_at     DateTime   @default(now()) @db.Timestamptz(3)
  updated_at     DateTime   @default(now()) @db.Timestamptz(3)

  @@unique([id_pemilih, level_dukungan, id_calon])
}

enum LevelDukungan {
  A
  B
  C
  D
} // Real Enum Has Been Replaced

let nama = req.query.nama || "";
let limit = parseInt(req.query.limit) || 10; // Default Limit
let page = parseInt(req.query.page) || 1;

console.time('GET PAGINATED DATA')
let dukungan = await prisma.dukungan.findMany({
  where: {
    pemilih: {
      account: {
        full_name: {
          contains: nama,
          mode: 'insensitive'
        }
      }
    },
    id_calon: calon.id_calon,
  },
  select: {
    pemilih: {
      select: {
        id_pemilih: true,
        account: {
          select: {
            full_name: true
          }
        }
      }
    },
    surveyor: {
      select: {
        id_surveyor: true,
        account: {
          select: {
            full_name: true
          }
        }
      }
    },
    created_at: true
  },
  skip: limit * (page - 1),
  take: limit
});
console.timeEnd('GET PAGINATED DATA')

console.time('GET COUNT ALL DATA')
let total_data = await prisma.dukungan.count({
    where: {
        pemilih: {
            account: {
                full_name: {
                    contains: nama,
                    mode: 'insensitive'
                }
            }
        },
        id_calon: calon.id_calon,
    }
})
console.timeEnd('GET COUNT ALL DATA')

Environment & setup

OS: Windows 10, MacOS Big Sur (11.7.X), MacOS Venture (13.1), Google App Engine (Not sure what google using)
Database: PostgreSQL 14
Node.js version: 18

Prisma Version

prisma                  : 4.9.0
@prisma/client          : 4.9.0
Current platform        : windows
Query Engine (Node-API) : libquery-engine ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5 (at node_modules\@prisma\engines\query_engine-windows.dll.node)
Migration Engine        : migration-engine-cli ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5 (at node_modules\@prisma\engines\migration-engine-windows.exe)
Introspection Engine    : introspection-core ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5 (at node_modules\@prisma\engines\introspection-engine-windows.exe)
Format Binary           : prisma-fmt ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5 (at node_modules\@prisma\engines\prisma-fmt-windows.exe)
Format Wasm             : @prisma/prisma-fmt-wasm 4.9.0-42.ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5
Default Engines Hash    : ceb5c99003b99c9ee2c1d2e618e359c14aef2ea5
Studio                  : 0.479.0
Preview Features        : filteredRelationCount

That looks ... weird. We will try to reproduce.

To maybe help us in understanding: 1 dukungan can have n pemilih which then has 1 accounts - is that correct? And your search wants to show all dukungan that are connected to an accounts where full_name contains a certain string?

That looks ... weird. We will try to reproduce.

To maybe help us in understanding: 1 dukungan can have n pemilih which then has 1 accounts - is that correct? And your search wants to show all dukungan that are connected to an accounts where full_name contains a certain string?

1 dukungan can only have 1 pemilih then 1 pemilih can only have 1 accounts
1 pemilih can have n dukungan

and i want to show all dukungan that connected to pemilih then connected to accounts where accounts.full_name contains some string.

anyway thanks for the response!

Ah right, I was reading the wrong direction again.

While it is still generating the seed data for me right now, maybe a (somewhat offtopic but still related) question: Wouldn't it be easier to write the query starting with account with its where condition, and then include the pemilih and dukungan for the results it finds?

I can confirm the fundamental problem you are reporting:

PS C:\Users\Jan\Documents\throwaway\17406> node .
SIMULATE GET 10 PAGE, WITH SLEEP 3000ms EVERY ITERATION

=== ITERATION 1 START ===
GET PAGINATED DATA: 236.997ms
{ count: 400000 }
GET COUNT ALL DATA: 640.082ms
PROCESS TIME: 878.821ms
=== ITERATION 1 END ===

=== ITERATION 2 START ===
GET PAGINATED DATA: 17.055ms
{ count: 400000 }
GET COUNT ALL DATA: 609.121ms
PROCESS TIME: 627.562ms
=== ITERATION 2 END ===

=== ITERATION 3 START ===
GET PAGINATED DATA: 16.535ms
{ count: 400000 }
GET COUNT ALL DATA: 631.485ms
PROCESS TIME: 649.25ms
=== ITERATION 3 END ===

=== ITERATION 4 START ===
GET PAGINATED DATA: 19.444ms
{ count: 400000 }
GET COUNT ALL DATA: 627.771ms
PROCESS TIME: 648.533ms
=== ITERATION 4 END ===

=== ITERATION 5 START ===
GET PAGINATED DATA: 16.434ms
{ count: 400000 }
GET COUNT ALL DATA: 599.902ms
PROCESS TIME: 618.177ms
=== ITERATION 5 END ===

=== ITERATION 6 START ===
GET PAGINATED DATA: 19.338ms
{ count: 400000 }
GET COUNT ALL DATA: 10.535s
PROCESS TIME: 10.556s
=== ITERATION 6 END ===

=== ITERATION 7 START ===
GET PAGINATED DATA: 9.101ms
{ count: 400000 }
GET COUNT ALL DATA: 9.916s
PROCESS TIME: 9.926s
=== ITERATION 7 END ===

=== ITERATION 8 START ===
GET PAGINATED DATA: 10.732ms
{ count: 400000 }
GET COUNT ALL DATA: 8.596s
...

Ah right, I was reading the wrong direction again.

While it is still generating the seed data for me right now, maybe a (somewhat offtopic but still related) question: Wouldn't it be easier to write the query starting with account with its where condition, and then include the pemilih and dukungan for the results it finds?

will try this approach, thanks for your support

Here with full query logging and duration, one normal and one super slow one:

=== ITERATION 5 START ===
Query: SELECT "public"."dukungan"."id_dukungan", "public"."dukungan"."id_pemilih", "public"."dukungan"."id_surveyor", "public"."dukungan"."created_at" FROM "public"."dukungan" WHERE ("public"."dukungan"."id_dukungan") IN (SELECT "t0"."id_dukungan" FROM "public"."dukungan" AS "t0" INNER JOIN "public"."pemilih" AS "j0" ON ("j0"."id_pemilih") = ("t0"."id_pemilih") WHERE (("j0"."id_pemilih") IN (SELECT "t1"."id_pemilih" FROM "public"."pemilih" AS "t1" INNER JOIN "public"."accounts" AS "j1" ON ("j1"."id_account") = ("t1"."id_account") WHERE ("j1"."full_name" ILIKE $1 AND "t1"."id_pemilih" IS NOT NULL)) AND "t0"."id_dukungan" IS NOT NULL)) ORDER BY "public"."dukungan"."id_dukungan" ASC LIMIT $2 OFFSET $3
Params: ["%%",10,40]
Duration: 6ms
Query: SELECT "public"."pemilih"."id_pemilih", "public"."pemilih"."id_account" FROM "public"."pemilih" WHERE "public"."pemilih"."id_pemilih" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["d08c17e5-0619-4ca2-b472-8015ba3712c3","d8a4658a-5a62-4fc1-b77d-07a8df9d84b6","341961ff-2e05-4db5-b76f-0c97979259ed","70d6524b-bcdb-44ae-afc1-1879dd1a259a","a6a5ec89-b03b-4cf2-9501-be067c9f7f0f","2683bd63-960c-403f-b084-6ea245621bc2","35d1aea1-6bb1-49a0-bfc4-785780559b1a","f1944b01-77bb-4345-be44-d0fc26f88bd0","276d6f3d-0425-4105-8ae1-062114cd5669","aec3d04e-4b25-49cc-8a7d-1077ef640458",0]
Duration: 0ms
Query: SELECT "public"."accounts"."id_account", "public"."accounts"."full_name" FROM "public"."accounts" WHERE "public"."accounts"."id_account" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["424065bd-c2c7-49dc-8f4f-615a7ca349a8","087c266e-b4b2-4fa8-8e75-4b286d0c5789","796a58dd-a820-4ddc-9e46-17f7c7f70679","291131ed-de48-4511-b78d-416df9df88fd","86590504-adce-4032-bd4f-de39e4941ca3","164d7bb7-931a-458f-bdee-b1f0c886ae1e","18756e55-d7d4-4cff-935c-475beeb03f18","061dec5b-5a20-4a83-ad80-ff63e7bb04d0","425a9a48-c9db-4bf5-bba3-33f11c965018","6afa5c7b-601c-429a-8f23-be461693be27",0]
Duration: 0ms
Query: SELECT "public"."surveyor"."id_surveyor", "public"."surveyor"."id_account" FROM "public"."surveyor" WHERE "public"."surveyor"."id_surveyor" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9) OFFSET $10
Params: ["905db05f-4e90-4120-aaee-4d1f8fb2fac8","f6cfa26d-ab54-4545-bfe3-d976ac5feee5","e29d9186-67de-464f-8121-b74be83d1a67","36de065d-76a3-4a18-b086-3850b0f61832","583f8487-2dc6-4258-9903-ef8a03c7128f","9e487640-8c68-4386-8a42-858bc9ef0377","fe3f8445-ffb6-4058-ac21-80511636bd58","1eb87f5c-2878-471f-9986-9ebfc0690e69","09710c93-c963-49ae-810c-7a27f6299e00",0]
Duration: 0ms
Query: SELECT "public"."accounts"."id_account", "public"."accounts"."full_name" FROM "public"."accounts" WHERE "public"."accounts"."id_account" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9) OFFSET $10
Params: ["07baac16-649b-4fe3-b5ff-45f8ff26f60c","1e110c21-66e9-4327-b44c-b179c74d39f8","6e632015-0966-42b3-a834-c7b460cd6ac3","a89683d5-ac68-4d92-aef2-8d03f99ba3e4","b609cbb5-bdc1-467d-a1fe-6b288839a949","80892bb1-ff8b-4a4b-be1c-068f3e88c7d6","17958786-56f0-4f46-8de3-411280600544","14af81f5-1691-4746-b051-548d22d68398","3c57124f-46e6-410e-92b0-81494cff8487",0]
Duration: 1ms
GET PAGINATED DATA: 21.58ms
Query: SELECT COUNT(*) FROM (SELECT "public"."dukungan"."id_dukungan" FROM "public"."dukungan" WHERE ("public"."dukungan"."id_dukungan") IN (SELECT "t0"."id_dukungan" FROM "public"."dukungan" AS "t0" INNER JOIN "public"."pemilih" AS "j0" ON ("j0"."id_pemilih") = ("t0"."id_pemilih") WHERE (("j0"."id_pemilih") IN (SELECT "t1"."id_pemilih" FROM "public"."pemilih" AS "t1" INNER JOIN "public"."accounts" AS "j1" ON ("j1"."id_account") = ("t1"."id_account") WHERE ("j1"."full_name" ILIKE $1 AND "t1"."id_pemilih" IS NOT NULL)) AND "t0"."id_dukungan" IS NOT NULL)) OFFSET $2) AS "sub"
Params: ["%%",0]
Duration: 628ms
GET COUNT ALL DATA: 633.261ms
PROCESS TIME: 655.796ms
=== ITERATION 5 END ===

=== ITERATION 6 START ===
Query: SELECT 1
Params: []
Duration: 0ms
Query: SELECT "public"."dukungan"."id_dukungan", "public"."dukungan"."id_pemilih", "public"."dukungan"."id_surveyor", "public"."dukungan"."created_at" FROM "public"."dukungan" WHERE ("public"."dukungan"."id_dukungan") IN (SELECT "t0"."id_dukungan" FROM "public"."dukungan" AS "t0" INNER JOIN "public"."pemilih" AS "j0" ON ("j0"."id_pemilih") = ("t0"."id_pemilih") WHERE (("j0"."id_pemilih") IN (SELECT "t1"."id_pemilih" FROM "public"."pemilih" AS "t1" INNER JOIN "public"."accounts" AS "j1" ON ("j1"."id_account") = ("t1"."id_account") WHERE ("j1"."full_name" ILIKE $1 AND "t1"."id_pemilih" IS NOT NULL)) AND "t0"."id_dukungan" IS NOT NULL)) ORDER BY "public"."dukungan"."id_dukungan" ASC LIMIT $2 OFFSET $3
Params: ["%%",10,50]
Duration: 3ms
Query: SELECT "public"."pemilih"."id_pemilih", "public"."pemilih"."id_account" FROM "public"."pemilih" WHERE "public"."pemilih"."id_pemilih" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["511e547d-321a-4f01-993a-62afc28a723e","153c0caa-a39b-4b5b-a49b-92c1d02614a1","bbc06128-1554-456b-8139-5cd3aa839ec9","7c0b750a-4481-49a9-bdc0-23a398b1eadc","2232a5b9-78fb-493e-ad7c-7b16a9f745bf","04f898bd-9e18-4969-8d87-83b1e2112bfe","f9df4250-8367-419a-a27f-76e66d4dbcee","6a7d13c2-79f3-45c5-b9c8-d8eaf9061329","ec050f10-a2f0-44c8-9ccc-f47cd52c17ab","50c992a5-a6ab-40f1-abcf-056fd6556d4a",0]
Duration: 0ms
Query: SELECT "public"."accounts"."id_account", "public"."accounts"."full_name" FROM "public"."accounts" WHERE "public"."accounts"."id_account" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["4027280c-fbf4-49b4-8338-6fcced21e84b","dcd788df-8310-4a9b-8f7c-19eb5a64f919","703493c3-0566-4b69-9e33-c57d8efd1457","55dc6106-4e90-4bce-8766-ed07419d5b86","6b72e048-81ff-43ea-80c7-4992cc1dca32","c090bd23-2887-46d5-b5fe-c117b99fcb79","12de616d-036c-49ad-9164-57f11e0e6ea4","a1de954d-fb8b-40f2-8940-9f01ecb4c9d3","1f91cc43-5906-4f65-ae87-8165d22be777","1545cc1b-03e9-40c8-9b71-e0f959aa1d46",0]
Duration: 0ms
Query: SELECT "public"."surveyor"."id_surveyor", "public"."surveyor"."id_account" FROM "public"."surveyor" WHERE "public"."surveyor"."id_surveyor" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["4fee164a-8372-4463-8bd8-1786a711d938","a28eff78-5d4a-46e8-ad21-347daeccd00a","b89d48a5-aef5-45dd-ba24-c264ba851d87","0b23f4be-1b09-4390-90cc-bfbbb3ea09ea","a44f1fae-4621-45aa-b3f6-402e82942804","008bb324-e391-45c2-a48c-fda253606c4d","199eaa10-e61c-4b81-a8f7-e2c13081a098","ec12993a-a3d2-4236-ba58-51011fbd3b6d","1a4a4468-941e-4080-b9f2-3ecca6d471ed","c6f946ef-7f12-4300-b631-dd2b87dc9b3c",0]
Duration: 0ms
Query: SELECT "public"."accounts"."id_account", "public"."accounts"."full_name" FROM "public"."accounts" WHERE "public"."accounts"."id_account" IN ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10) OFFSET $11
Params: ["06abf556-0d90-4313-9d3d-b1dd2f41f960","c0864709-6798-4f9a-adb2-6eb92a1e52d6","db27ab09-19e8-4520-8eba-0594a0ea83cc","cad0993b-3d5d-45cb-bfa0-661d29fca25b","0889a9f9-2087-4485-91bd-2e85b7f5d454","ac5c7c26-7513-42b1-bc37-7ac8a6b5746c","52dc4dac-66ea-4d2a-b143-d91d933f4b7c","eaf5df82-e768-45ad-a3b3-38c1ac751f49","c8caca4a-c764-4509-ad33-8c582da05d96","5c8add59-8f7c-48ee-9769-edc4a765276e",0]
Duration: 0ms
GET PAGINATED DATA: 15.711ms
Debugger attached.
Query: SELECT COUNT(*) FROM (SELECT "public"."dukungan"."id_dukungan" FROM "public"."dukungan" WHERE ("public"."dukungan"."id_dukungan") IN (SELECT "t0"."id_dukungan" FROM "public"."dukungan" AS "t0" INNER JOIN "public"."pemilih" AS "j0" ON ("j0"."id_pemilih") = ("t0"."id_pemilih") WHERE (("j0"."id_pemilih") IN (SELECT "t1"."id_pemilih" FROM "public"."pemilih" AS "t1" INNER JOIN "public"."accounts" AS "j1" ON ("j1"."id_account") = ("t1"."id_account") WHERE ("j1"."full_name" ILIKE $1 AND "t1"."id_pemilih" IS NOT NULL)) AND "t0"."id_dukungan" IS NOT NULL)) OFFSET $2) AS "sub"
Params: ["%%",0]
Duration: 7898ms
GET COUNT ALL DATA: 7.904s
PROCESS TIME: 7.921s
=== ITERATION 6 END ===

Next step: Get actual query duration from database to see if this is on the database or Prisma Client/Engine side.

here some interesting info. it seems count by ORM are the problem, when i try using raw query using this project https://github.com/BagasNS/prisma-reproduce-slow-query it working properly.

but the wierd things is, if query count by ORM are the problem, why counting by ORM always start slowing down from iteration 6? (will be make sense if slow at all 😅)

FYI: when query is slowing down at iteration 6, its not affecting another query, only counting at same method are affected, no matter how much connection pooling are. For Example in my real project using express js, there are some middlewares then some input validations that using prisma query, then request forward to getDataPagination. middleware and input validation are ok when prisma slowing down at method getDataPagination

prisma / prisma