search

supabase / supavisor

A cloud-native, multi-tenant Postgres connection pooler.
https://supabase.github.io/supavisor/
Apache License 2.0
1.77k stars 58 forks source link

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

Open jensen opened 9 months ago

jensen commented 9 months ago

Bug report

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.

Connection CITEXT Duration
Supavisor Yes 1111ms
Supavisor No 277ms
Direct Yes 140ms
Direct No 139ms

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.

chasers commented 9 months 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.

jensen commented 9 months 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.

jensen commented 9 months 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
jensen commented 8 months 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.

jensen commented 8 months 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.