#300
Issues/stylessh/supavisor/#300

Queries on tables that use CITEXT are 4x slower when using Supavisor vs a direct connection to the db

Openjensenopened 2y ago

Bug report

  • I confirm this is a bug with Supabase, not with my own application.
  • I confirm I have searched the Docs, GitHub Discussions, and Discord.

Originally searched on discord and posted there, the amazing garyaustin suggested I post the issue on the Supavisor GitHub. https://discord.com/channels/839993398554656828/1204584952029782026

I also tested this issue with a local install of Supavisor following the instructions found here: https://supabase.github.io/supavisor/

Describe the bug

Queries to tables that use the CITEXT type are taking longer than queries on tables that do not use this type. Even if the query is select * from table. This bug can be described as weird because it does not seem to occur when connecting to the database directly.

ConnectionCITEXTDuration
SupavisorYes1111ms
SupavisorNo277ms
DirectYes140ms
DirectNo139ms

Background:

We setup a Supabase instance in eu-west-2, but are doing the development in us-west. This means that our queries have about 110ms of extra latency which is acceptable. Recently we noticed that queries to the users table are taking about 1200-1500ms while queries to other tables are taking less than 300ms. We recently switched to the Supavisor pooler, and do not recall if the queries were slow when we were using PGbouncer.

In an attempt to isolate the issue to Prisma, I tried Drizzle. The queries with Drizzle are also slow on the users tables. The query performance in the Supabase monitoring shows 0.04ms for this query after resetting and running it.

To Reproduce

  1. Setup a new Supabase instance, the farther away the more pronounced the difference in duration.
  2. Install CITEXT extension
  3. Add a table that has a few columns that use the CITEXT type. In our case we have a users table with email, firstName and lastName that are of type CITEXT.
  4. Add a table that has a few columns, but do not use the CITEXT type.
  5. Connect with Prisma with postgres://postgres.tenant:password@region.supabase.com:6543/postgres?pgbouncer=true
  6. Query from the first table with something like select * from users and record the duration.
  7. Query from the second table with something like select * from centres and record the duration.

Expected behavior

The queries should take the same duration when using the connection pooler.

Logs

Connection to Supavisor eu-west-2 (no CITEXT):

Query: SELECT "public"."centres"."id", "public"."centres"."isActive", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE ("public"."centres"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["15608625-5160-4528-a4c4-01aad2f8a69f",1,0]
Duration: 276ms

... BEGIN; COMMIT; ETC....

Query: SELECT "public"."users"."id", "public"."users"."isActive", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt", "public"."users"."phone" FROM "public"."users" WHERE ("public"."users"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["d9b1f093-1b46-4d8f-b149-30a1e80dc62e",1,0]
Duration: 277ms

Connection to Supavisor eu-west-2:

Query: SELECT "public"."centres"."id", "public"."centres"."isActive", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE ("public"."centres"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["15608625-5160-4528-a4c4-01aad2f8a69f",1,0]
Duration: 277ms

... BEGIN; COMMIT; ETC....

Query: SELECT "public"."users"."id", "public"."users"."isActive", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt", "public"."users"."phone" FROM "public"."users" WHERE ("public"."users"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["d9b1f093-1b46-4d8f-b149-30a1e80dc62e",1,0]
Duration: 1111ms

Connection to Postgres directly using 5432 (no CITEXT):

Query: SELECT "public"."centres"."id", "public"."centres"."isActive", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE ("public"."centres"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["15608625-5160-4528-a4c4-01aad2f8a69f",1,0]
Duration: 140ms

... BEGIN; COMMIT; ETC....

Query: SELECT "public"."users"."id", "public"."users"."isActive", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt", "public"."users"."phone" FROM "public"."users" WHERE ("public"."users"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["d9b1f093-1b46-4d8f-b149-30a1e80dc62e",1,0]
Duration: 139ms

Connection to Postgres directly using 5432:

Query: SELECT "public"."centres"."id", "public"."centres"."isActive", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE ("public"."centres"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["15608625-5160-4528-a4c4-01aad2f8a69f",1,0]
Duration: 142ms

... BEGIN; COMMIT; ETC....

Query: SELECT "public"."users"."id", "public"."users"."isActive", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt", "public"."users"."phone" FROM "public"."users" WHERE ("public"."users"."id" = $1 AND 1=1) LIMIT $2 OFFSET $3
Params: ["d9b1f093-1b46-4d8f-b149-30a1e80dc62e",1,0]
Duration: 140ms

Additional context

The logs show that the query for centres is approximately the same duration with or without he connection pooler. The users table query duration matches when CITEXT isn't used as a column type within the table. The duration increases as the table uses more columns that with the CITEXT type.

Activity

6
chasers2y ago

Interesting. Thank you for the detail here!

Maybe something in the wire protocol causes more round trips for citext tables.

We don't do anything specific for any types.

jensen2y ago

Thank you for taking a look. I didn't imagine anything was being done specifically with types.

Round trips sounds like a good path to investigate since I noticed adding 1 CITEXT type was faster than adding 3. I imagine adding more would slow it down further. It also seemed like the timing scales relative to the overall single query time.

jensen2y ago

I had a bit of time to point my development instance of supavisor to an eu-west-2 supabase DB. These are the logs from the same query with three different column type configurations.

Query (no CITEXT columns):

Query: SELECT "public"."users"."id", "public"."users"."isArchived", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."phone", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt" FROM "public"."users" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 296ms

Supavisor:

16:27:41.608 [debug] ClientHandler: Skip prepared statement false file=lib/supavisor/client_handler.ex line=890 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.608 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.751 [debug] DbHandler: Got write replica message <<84, 0, 0, 0, 33, 0, 1, 63, 99, 111, 108, 117, 109, 110, 63, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 23, 0, 4, 255, 255, 255, 255, 0, 0, 68, 0, 0, 0, 11, 0, 1, 0, 0, 0, 1, 49, 67, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.829.0> project=dev_tenant user=postgres mode=transaction 
16:27:41.751 [debug] ClientHandler: --> --> bin 66 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.751 [debug] ClientHandler: Client is ready file=lib/supavisor/client_handler.ex line=487 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.751 [debug] ClientHandler: Call timeout {:heartbeat_interval, 60000} file=lib/supavisor/client_handler.ex line=900 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.752 [debug] ClientHandler: Skip prepared statement false file=lib/supavisor/client_handler.ex line=890 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.752 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.893 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 10, 66, 69, 71, 73, 78, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:41.893 [debug] ClientHandler: --> --> bin 17 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.893 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:41.893 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.034 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 19, 68, 69, 65, 76, 76, 79, 67, 65, 84, 69, 32, 65, 76, 76, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:42.034 [debug] ClientHandler: --> --> bin 26 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.035 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.035 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.175 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 20, 84, 0, 0, 1, 9, 0, 10, 105, 100, 0, 0, 0, 146, 23, 0, 1, 0, 0, 11, 134, 0, 16, 255, 255, 255, 255, 0, 0, 105, 115, 65, 114, 99, 104, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:42.175 [debug] ClientHandler: --> --> bin 288 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.175 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.176 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.315 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 156, 0, 10, 0, 0, 0, 16, 160, 46, 189, 130, 143, 32, 76, 114, 154, 41, 13, 71, 53, 166, 248, 19, 0, 0, 0, 1, 0, 0, 0, 0, 19, 68, 101, 98, 111, 114, 97, 104, 50, 50, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:42.315 [debug] DbHandler: Got write replica message <<75, 108, 111, 99, 107, 111, 0, 0, 0, 15, 109, 56, 69, 122, 72, 100, 110, 100, 80, 65, 121, 66, 105, 107, 84, 0, 0, 0, 21, 49, 45, 53, 53, 50, 45, 50, 53, 57, 45, 52, 53, 52, 51, 32, 120, 48, 56, 50, 54, 55, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:42.316 [debug] ClientHandler: --> --> bin 1460 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.316 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.316 [debug] ClientHandler: --> --> bin 452 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.316 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.317 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.456 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84, 67, 0, 0, 0, 11, 67, 79, 77, 77, 73, 84, 0, 90, 0, 0, 0, 5, 73>> file=lib/supavisor/db_handler.ex line=334 pid=<0.828.0> project=dev_tenant user=postgres mode=transaction 
16:27:42.456 [debug] ClientHandler: --> --> bin 29 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.457 [debug] ClientHandler: Client is ready file=lib/supavisor/client_handler.ex line=487 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single 
16:27:42.457 [debug] ClientHandler: Call timeout {:heartbeat_interval, 60000} file=lib/supavisor/client_handler.ex line=900 pid=<0.850.0> project=dev_tenant user=postgres mode=transaction type=single

Query (email, firstName, lastName as CITEXT):

Query: SELECT "public"."users"."id", "public"."users"."isArchived", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."phone", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt" FROM "public"."users" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 1166ms

Supavisor:

16:02:13.614 [debug] ClientHandler: Skip prepared statement false file=lib/supavisor/client_handler.ex line=890 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.615 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.761 [debug] DbHandler: Got write replica message <<84, 0, 0, 0, 33, 0, 1, 63, 99, 111, 108, 117, 109, 110, 63, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 23, 0, 4, 255, 255, 255, 255, 0, 0, 68, 0, 0, 0, 11, 0, 1, 0, 0, 0, 1, 49, 67, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.827.0> project=dev_tenant user=postgres mode=transaction 
16:02:13.761 [debug] ClientHandler: --> --> bin 66 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.761 [debug] ClientHandler: Client is ready file=lib/supavisor/client_handler.ex line=487 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.762 [debug] ClientHandler: Call timeout {:heartbeat_interval, 60000} file=lib/supavisor/client_handler.ex line=900 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.762 [debug] ClientHandler: Skip prepared statement false file=lib/supavisor/client_handler.ex line=890 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.763 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.907 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 10, 66, 69, 71, 73, 78, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:13.907 [debug] ClientHandler: --> --> bin 17 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.907 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:13.908 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.053 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 19, 68, 69, 65, 76, 76, 79, 67, 65, 84, 69, 32, 65, 76, 76, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.053 [debug] ClientHandler: --> --> bin 26 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.053 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.053 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.199 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 20, 84, 0, 0, 1, 9, 0, 10, 105, 100, 0, 0, 0, 146, 23, 0, 1, 0, 0, 11, 134, 0, 16, 255, 255, 255, 255, 0, 0, 105, 115, 65, 114, 99, 104, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.199 [debug] ClientHandler: --> --> bin 288 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.199 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.199 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.344 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 26, 84, 0, 0, 0, 196, 0, 7, 116, 121, 112, 110, 97, 109, 101, 0, 0, 0, 4, 223, 0, 2, 0, 0, 0, 19, 0, 64, 255, 255, 255, 255, 0, 0, 116, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.344 [debug] ClientHandler: --> --> bin 219 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.344 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.345 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.489 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 63, 0, 7, 0, 0, 0, 6, 99, 105, 116, 101, 120, 116, 0, 0, 0, 1, 98, 0, 0, 0, 4, 0, 0, 0, 0, 255, 255, 255, 255, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.490 [debug] ClientHandler: --> --> bin 89 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.490 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.490 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.634 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.634 [debug] ClientHandler: --> --> bin 11 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.634 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.635 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 26, 84, 0, 0, 0, 196, 0, 7, 116, 121, 112, 110, 97, 109, 101, 0, 0, 0, 4, 223, 0, 2, 0, 0, 0, 19, 0, 64, 255, 255, 255, 255, 0, 0, 116, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.635 [debug] ClientHandler: --> --> bin 219 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.635 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.635 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.779 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 63, 0, 7, 0, 0, 0, 6, 99, 105, 116, 101, 120, 116, 0, 0, 0, 1, 98, 0, 0, 0, 4, 0, 0, 0, 0, 255, 255, 255, 255, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.780 [debug] ClientHandler: --> --> bin 89 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.780 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.780 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.928 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84, 49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 26, 84, 0, 0, 0, 196, 0, 7, 116, 121, 112, 110, 97, 109, 101, 0, 0, 0, 4, 223, 0, 2, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:14.928 [debug] ClientHandler: --> --> bin 230 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.928 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:14.928 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.072 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 63, 0, 7, 0, 0, 0, 6, 99, 105, 116, 101, 120, 116, 0, 0, 0, 1, 98, 0, 0, 0, 4, 0, 0, 0, 0, 255, 255, 255, 255, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:15.072 [debug] ClientHandler: --> --> bin 89 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.072 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.072 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.218 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:15.218 [debug] ClientHandler: --> --> bin 11 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.218 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.219 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 156, 0, 10, 0, 0, 0, 16, 160, 46, 189, 130, 143, 32, 76, 114, 154, 41, 13, 71, 53, 166, 248, 19, 0, 0, 0, 1, 0, 0, 0, 0, 19, 68, 101, 98, 111, 114, 97, 104, 50, 50, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:15.220 [debug] DbHandler: Got write replica message <<75, 108, 111, 99, 107, 111, 0, 0, 0, 15, 109, 56, 69, 122, 72, 100, 110, 100, 80, 65, 121, 66, 105, 107, 84, 0, 0, 0, 21, 49, 45, 53, 53, 50, 45, 50, 53, 57, 45, 52, 53, 52, 51, 32, 120, 48, 56, 50, 54, 55, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:15.220 [debug] ClientHandler: --> --> bin 1460 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.220 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.220 [debug] ClientHandler: --> --> bin 452 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.220 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.220 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.368 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84, 67, 0, 0, 0, 11, 67, 79, 77, 77, 73, 84, 0, 90, 0, 0, 0, 5, 73>> file=lib/supavisor/db_handler.ex line=334 pid=<0.826.0> project=dev_tenant user=postgres mode=transaction 
16:02:15.368 [debug] ClientHandler: --> --> bin 29 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.368 [debug] ClientHandler: Client is ready file=lib/supavisor/client_handler.ex line=487 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:02:15.368 [debug] ClientHandler: Call timeout {:heartbeat_interval, 60000} file=lib/supavisor/client_handler.ex line=900 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single

I also did a query on users where only the email column is CITEXT.

Query (email is CITEXT):

Query: SELECT "public"."users"."id", "public"."users"."isArchived", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."phone", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt" FROM "public"."users" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 587ms

Supavisor:

16:07:04.401 [debug] ClientHandler: Skip prepared statement false file=lib/supavisor/client_handler.ex line=890 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.401 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.548 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 10, 66, 69, 71, 73, 78, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:04.548 [debug] ClientHandler: --> --> bin 17 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.548 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.549 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.765 [debug] DbHandler: Got write replica message <<67, 0, 0, 0, 19, 68, 69, 65, 76, 76, 79, 67, 65, 84, 69, 32, 65, 76, 76, 0, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:04.765 [debug] ClientHandler: --> --> bin 26 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.765 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.766 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.912 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 20, 84, 0, 0, 1, 9, 0, 10, 105, 100, 0, 0, 0, 146, 23, 0, 1, 0, 0, 11, 134, 0, 16, 255, 255, 255, 255, 0, 0, 105, 115, 65, 114, 99, 104, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:04.912 [debug] ClientHandler: --> --> bin 288 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.912 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:04.912 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.057 [debug] DbHandler: Got write replica message <<49, 0, 0, 0, 4, 116, 0, 0, 0, 10, 0, 1, 0, 0, 0, 26, 84, 0, 0, 0, 196, 0, 7, 116, 121, 112, 110, 97, 109, 101, 0, 0, 0, 4, 223, 0, 2, 0, 0, 0, 19, 0, 64, 255, 255, 255, 255, 0, 0, 116, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.058 [debug] ClientHandler: --> --> bin 219 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.058 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.058 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.205 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 63, 0, 7, 0, 0, 0, 6, 99, 105, 116, 101, 120, 116, 0, 0, 0, 1, 98, 0, 0, 0, 4, 0, 0, 0, 0, 255, 255, 255, 255, 0, 0, 0, 4, 0, 0, 0, 0, 0, 0, 0, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.206 [debug] ClientHandler: --> --> bin 89 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.206 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.206 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.349 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.349 [debug] ClientHandler: --> --> bin 11 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.349 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.352 [debug] DbHandler: Got write replica message <<50, 0, 0, 0, 4, 68, 0, 0, 0, 156, 0, 10, 0, 0, 0, 16, 160, 46, 189, 130, 143, 32, 76, 114, 154, 41, 13, 71, 53, 166, 248, 19, 0, 0, 0, 1, 0, 0, 0, 0, 19, 68, 101, 98, 111, 114, 97, 104, 50, 50, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.352 [debug] DbHandler: Got write replica message <<75, 108, 111, 99, 107, 111, 0, 0, 0, 15, 109, 56, 69, 122, 72, 100, 110, 100, 80, 65, 121, 66, 105, 107, 84, 0, 0, 0, 21, 49, 45, 53, 53, 50, 45, 50, 53, 57, 45, 52, 53, 52, 51, 32, 120, 48, 56, 50, 54, 55, ...>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.352 [debug] ClientHandler: --> --> bin 1460 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.352 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.352 [debug] ClientHandler: --> --> bin 452 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.352 [debug] ClientHandler: Client is not ready file=lib/supavisor/client_handler.ex line=499 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.353 [debug] ClientHandler: DbHandler call success file=lib/supavisor/client_handler.ex line=420 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.498 [debug] DbHandler: Got write replica message <<51, 0, 0, 0, 4, 90, 0, 0, 0, 5, 84, 67, 0, 0, 0, 11, 67, 79, 77, 77, 73, 84, 0, 90, 0, 0, 0, 5, 73>> file=lib/supavisor/db_handler.ex line=334 pid=<0.831.0> project=dev_tenant user=postgres mode=transaction 
16:07:05.498 [debug] ClientHandler: --> --> bin 29 bytes file=lib/supavisor/client_handler.ex line=483 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.498 [debug] ClientHandler: Client is ready file=lib/supavisor/client_handler.ex line=487 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single 
16:07:05.498 [debug] ClientHandler: Call timeout {:heartbeat_interval, 60000} file=lib/supavisor/client_handler.ex line=900 pid=<0.819.0> project=dev_tenant user=postgres mode=transaction type=single
jensen2y ago

I have been able to reproduce this with PgBouncer now so it is seeming more likely that this has to do with CITEXT and transaction mode that we use for the connection poolers.

Users table has CITEXT for firstName, lastName and email.

Query: SELECT 1
Params: []
Duration: 83ms
Query: BEGIN
Params: []
Duration: 84ms
Query: DEALLOCATE ALL
Params: []
Duration: 84ms
Query: SELECT "public"."users"."id", "public"."users"."isArchived", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."phone", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt" FROM "public"."users" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 683ms
Query: COMMIT
Params: []
Duration: 85ms
Query: BEGIN
Params: []
Duration: 83ms
Query: DEALLOCATE ALL
Params: []
Duration: 84ms
Query: SELECT "public"."centres"."id", "public"."centres"."isArchived", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 167ms
Query: COMMIT
Params: []
Duration: 83ms
GET /login 200 - - 1453.404 ms

Users table has no CITEXT columns.

Query: BEGIN
Params: []
Duration: 82ms
Query: DEALLOCATE ALL
Params: []
Duration: 84ms
Query: SELECT "public"."users"."id", "public"."users"."isArchived", "public"."users"."email", "public"."users"."firstName", "public"."users"."lastName", "public"."users"."password", "public"."users"."phone", "public"."users"."role", "public"."users"."createdAt", "public"."users"."updatedAt" FROM "public"."users" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 168ms
Query: COMMIT
Params: []
Duration: 84ms
Query: BEGIN
Params: []
Duration: 84ms
Query: DEALLOCATE ALL
Params: []
Duration: 83ms
Query: SELECT "public"."centres"."id", "public"."centres"."isArchived", "public"."centres"."centreName", "public"."centres"."createdAt", "public"."centres"."updatedAt", "public"."centres"."userId", "public"."centres"."adminId" FROM "public"."centres" WHERE 1=1 OFFSET $1
Params: [0]
Duration: 192ms
Query: COMMIT
Params: []
Duration: 91ms
GET /login 200 - - 882.331 ms

It seems to me that at this point the CITEXT extension is incompatible with transaction mode for production purposes. I will work towards finding an alternative.

jensen2y ago

I created a configuration with Cloudflare that seems to avoid this issue.

Remix (drizzle w/ HTTP proxy) -> CF Worker (connected using a service binding) -> Hyperdrive (CF Pooler) -> DB (direct connection 5432)

I added 10 CITEXT columns to a table and didn't notice any major difference in the query times compared to a table without this type.

abidedavana3mo ago

Followed up on this and I'm fairly confident the slowdown isn't happening inside Supavisor , it's client-side in Prisma, and it reproduces with no pooler in the path at all.

The mechanism: with pgbouncer=true, Prisma's engine runs DEALLOCATE ALL at the start of every transaction and drops its per-connection statement/type caches. citext is an extension type, so its OID is assigned at CREATE EXTENSION time and isn't known to the client statically the way text is. So on every transaction Prisma re-resolves the OID with SELECT ... FROM pg_type lookups, and the number of extra round trips scales with the number of citext columns — which matches what you saw with 1 column vs 3. A text-only table skips those lookups entirely, hence the ~4x gap.

Two things convinced me it isn't Supavisor:

  • Pointing Prisma with pgbouncer=true straight at Postgres (no Supavisor) shows the same ~4x.
  • Profiling the ClientHandler/DbHandler processes with :eprof during the slow query shows well under 1% of wall time spent in Supavisor — it's just relaying the round trips.

The good news is the fix is already on the Supavisor side: enable the named_prepared_statements feature flag and drop pgbouncer=true. That lets Prisma keep its caches in transaction mode, so the type lookups happen once at connection setup instead of on every transaction. Session mode avoids it too.

Local repro, ~70ms injected RTT, Prisma 6.19.3, users table with 3 citext columns (p50):

setupcitexttext
transaction + pgbouncer=true796ms363ms
transaction + named_prepared_statements, no pgbouncer=true82ms79ms
direct connection74ms—

Happy to put up a small docs PR describing this if it'd be useful.