Computed Relations slow at first request or after idle

[MHC2000]

Hello,

I'm using Postgrest 12.0.2 with postgresql 13.
Im Adding some additional 1:many columns in a request by a computed reference.
When I'm calling the query for the first time it takes over a minute after I get a response.
If I trigger the query again directly or in the next 5 minutes the response is below 100 ms.
After trying several attempts to optimize I figured the added content by computed relations (dt_129_lt_2956_fk) is the part which is slowing it down. But I don't know why it's working after the first query as wished.
Does Postgrest recache the relations between tables after some time?

The server reacts on other queries always fast around 100 and 300 ms.
Also tried the foreign key, but the same problem.

• Full query: dt_129?select=id,modified,created,software_project:cid_1499_data,lt_2956:dt_129_lt_2956_fk(*),modified,created&order=title.asc,id.asc&is_software_open=is.true&limit=50&offset=0

• View 129 looks like that:

CREATE OR REPLACE VIEW api.dt_129
 AS
 SELECT mt.id,
    mt.is_active,
    mt.created,
    mt.modified,
    mt.description,
    mt.is_software_open,
    mt.software_project,
    mt.software_project_branch,
    mt.title,
    cid_1499_data.summary AS cid_1499_data
   FROM software.software_major_versions mt
     LEFT JOIN LATERAL ( SELECT jsonb_build_object('id', ot.id, 'title', ot.title, 'label', ot.title) AS summary
           FROM software.software_projects ot
          WHERE ot.id = mt.software_project) cid_1499_data ON true;

ALTER TABLE api.dt_129
    OWNER TO admin_users;

• That is the linked table view:

CREATE OR REPLACE VIEW api.dt_129_lt_2956
 AS
 SELECT lt.id,
    lt.created,
    lt.modified,
    lt.is_active,
    lt.software_major_version,
    lt.swip_i_step2development_model_range,
    cid_1576_data.summary AS cid_1576_data
   FROM software.smv2swip_i_step lt
     LEFT JOIN LATERAL ( SELECT jsonb_build_object('id', ot.id, 'title', ot.title, 'label', ot.title) AS summary
           FROM master_data.swip_i_step2development_model_range ot
          WHERE ot.id = lt.swip_i_step2development_model_range) cid_1576_data ON true
  WHERE lt.is_active = true;

• The computed relation:

CREATE OR REPLACE FUNCTION api.dt_129_lt_2956_fk(
	mt api.dt_129)
    RETURNS SETOF api.dt_129_lt_2956 
    LANGUAGE 'sql'
    COST 100
    STABLE PARALLEL UNSAFE
    ROWS 1000

AS $BODY$
                SELECT lt.* 
                    FROM api.dt_129_lt_2956 lt
                    WHERE lt.software_major_version = mt.id
            
$BODY$;

Maybe somebody has an idea why the speed is at the beginning always very slow and then is for 10 minutes after the first request ok.

Thanks!

Manfred

[MHC2000]

I figured, that postgrest is reconnecting every 30 minutes. Is that normal?

08/Mar/2024:08:00:12 +0100: Retrying listening for notifications on the pgrst channel..
08/Mar/2024:08:00:12 +0100: Starting PostgREST 12.0.2...
08/Mar/2024:08:00:12 +0100: Attempting to connect to the database...
08/Mar/2024:08:00:12 +0100: Connection successful
08/Mar/2024:08:00:12 +0100: Config reloaded
08/Mar/2024:08:00:12 +0100: Listening for notifications on the pgrst channel
08/Mar/2024:08:00:14 +0100: Schema cache loaded
08/Mar/2024:08:30:12 +0100: Retrying listening for notifications on the pgrst channel..
08/Mar/2024:08:30:12 +0100: Starting PostgREST 12.0.2...
08/Mar/2024:08:30:12 +0100: Attempting to connect to the database...
08/Mar/2024:08:30:12 +0100: Connection successful
08/Mar/2024:08:30:12 +0100: Config reloaded
08/Mar/2024:08:30:12 +0100: Listening for notifications on the pgrst channel
08/Mar/2024:08:30:15 +0100: Schema cache loaded

[MHC2000]

So I've deactivated the NOTIFY mechanism and postgrest doesn't reload the schema every 30 minutes.
Also the query which was working quite differently every now and then is now stable.

But I'm still curious why the NOTIFY was triggered for postgrest.
I do have a procedure which triggers the NOTIFY after I rebuild a view or function for my api.
But this procedure is not called periodically and I don't have any automations on this database which could call this procedure.

Is it possible that the LISTEN channel of postgrest is disconnected every 30 minutes due to a database setting or something else?

[steve-chavez]

Is it possible that the LISTEN channel of postgrest is disconnected every 30 minutes due to a database setting or something else?

Yes, but that's dependent on your database provider.

In the table pg_settings I don't see any entry for idle_session_timeout, so I gues it's not set..

Maybe query pg_db_role_settings as well and check an entry for the connection role there

[MHC2000]

Yes, but that's dependent on your database provider.

It's within my company, but I haven't found any hints that there is something like that.
Other connections are lasting longer than 30 minutes and after turning the channel off, no reconnects of postgrest.

Maybe query pg_db_role_settings as well and check an entry for the connection role there

Just one entry with: {search_path=public}.
Nothing like connection role.

I guess the only way to figure that out, is to have an error message which tells where it's comming from.

[steve-chavez]

I guess the only way to figure that out, is to have an error message which tells where it's comming from.

Right. Trying to improve that on #3323

[MHC2000]

Perfect, thanks a lot for the help!

[steve-chavez]

@MHC2000 There are binaries (at the bottom of the page) that include the above fix on: https://github.com/PostgREST/postgrest/actions/runs/8241905872

Could you run the one that works on your platform and see what the logs show now?

[MHC2000]

This is what I got with the test version:

12/Mar/2024:09:16:59 +0100: Starting PostgREST 12.1...
12/Mar/2024:09:16:59 +0100: Attempting to connect to the database...
12/Mar/2024:09:16:59 +0100: Successfully connected to PostgreSQL 13.14 (Ubuntu 1                              3.14-1.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubunt                              u1~20.04.2) 9.4.0, 64-bit
12/Mar/2024:09:16:59 +0100: Listening on port 3000
12/Mar/2024:09:16:59 +0100: Config reloaded
12/Mar/2024:09:16:59 +0100: Listening for notifications on the pgrst channel
12/Mar/2024:09:17:02 +0100: Schema cache queried in 387.8 milliseconds
12/Mar/2024:09:17:02 +0100: Schema cache loaded 880 Relations, 3190 Relationship                              s, 1378 Functions, 0 Domain Representations, 4 Media Type Handlers
12/Mar/2024:09:18:40 +0100: Schema cache loaded in 96471.0 milliseconds
12/Mar/2024:09:46:59 +0100: FatalError {fatalErrorMessage = "Error checking for PostgreSQL notifications"}. Retrying listening for notifications on the pgrst channel..
12/Mar/2024:09:46:59 +0100: Attempting to connect to the database...
12/Mar/2024:09:46:59 +0100: Successfully connected to PostgreSQL 13.14 (Ubuntu 13.14-1.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.2) 9.4.0, 64-bit
12/Mar/2024:09:46:59 +0100: Config reloaded
12/Mar/2024:09:46:59 +0100: Listening for notifications on the pgrst channel
12/Mar/2024:09:47:02 +0100: Schema cache queried in 457.2 milliseconds
12/Mar/2024:09:47:02 +0100: Schema cache loaded 880 Relations, 3190 Relationships, 1378 Functions, 0 Domain Representations, 4 Media Type Handlers
12/Mar/2024:09:48:11 +0100: Schema cache loaded in 67784.3 milliseconds

So I guess there is an error during listening.
But I don't get why postgrest is reconnectiong, because without the listening to pgrst the connection is stable and there wasn't any reconnecting the last days. Or is this the fail safe after an error with the listening, reconnecting?

[steve-chavez]

But I don't get why postgrest is reconnectiong, because without the listening to pgrst the connection is stable and there wasn't any reconnecting the last days. Or is this the fail safe after an error with the listening, reconnecting?

It needs to reconnect + refresh cache because there might have been notifications sent when the LISTEN channel was down.

The pool conneciton must also be reset otherwise we might run into #2620 again.

diogob/hasql-notifications#20 should provide more details on the error message.