PostgREST takes a lot of time to make first embedding request with big schema

[laurenceisla]

Environment

• PostgreSQL version: v14
• PostgREST version: v10.0.0
• Operating system: EndeavourOS

Description of issue

Using the big schema in this repo as an example, the first PostgREST start up takes a little while, after that, doing this query:

curl 'localhost:3000/projects?select=clients(*)'

takes a very long time. This may have to do with searching inside the schema cache. The subsequent requests are fast though.

I tested this for PosgREST v8, v9 and v10 with the same results.

[wolfgangwalther]

I assume parsing the query result when loading the schema cache is actually done lazily - so only happens when the schema cache is used the first time.

[steve-chavez]

for instance if you read in a file, do some processing, and then print out some of the results, it's likely that any processing not needed by the output won't be evaluated. However, the entire file will be read, even parts you never use.

From https://stackoverflow.com/a/2777842/4692662

The above is what is happening on our case. Just replace "reading from file" with "querying the db".

I'm working on a logging improvement that clears the difference between "querying the schema cache" and "parsing the schema cache".

PGRST_DB_SCHEMAS="apflora" PGRST_DB_PLAN_ENABLED=1 PGRST_SERVER_TIMING_ENABLED=1  PGRST_ADMIN_SERVER_PORT=3001 PGRST_SERVER_HOST='*6' postgrest-with-post
gresql-15 -f test/io/big_schema.sql  postgrest-run
postgrest-with-postgresql-15: You can connect with: psql 'postgres:///postgres?host=/run/user/1000/postgrest/postgrest-with-postgresql-15-Acv/socket' -U postgres
postgrest-with-postgresql-15: You can tail the logs with: tail -f /run/user/1000/postgrest/postgrest-with-postgresql-15-Acv/db.log
06/Feb/2024:23:16:31 -0500: Starting PostgREST 11.2.0 (eaa1d81)...
06/Feb/2024:23:16:31 -0500: Attempting to connect to the database...
06/Feb/2024:23:16:31 -0500: Connection successful
06/Feb/2024:23:16:31 -0500: Admin server listening on port 3001
06/Feb/2024:23:16:31 -0500: Listening on port 3000
06/Feb/2024:23:16:31 -0500: Listening for notifications on the pgrst channel
06/Feb/2024:23:16:31 -0500: Config reloaded
06/Feb/2024:23:16:31 -0500: Schema cache queried in 45.7 milliseconds
06/Feb/2024:23:16:31 -0500: Relations: 326, Relationships: 305, Routines: 6, Domain Representations: 0, Media Type Handlers: 4
06/Feb/2024:23:16:51 -0500: Schema cache parsed in 19791.0 milliseconds. 

Now it can be seen that parsing takes longer than querying on the big_schema.

[steve-chavez]

06/Feb/2024:23:16:51 -0500: Schema cache parsed in 19791.0 milliseconds.

Decided not to show that part in #3213. The user cannot do anything for slowing down the parsing time. It could be confusing to include it.

The logs now look like:

09/Feb/2024:16:14:02 -0500: Schema cache queried in 19.6 milliseconds
09/Feb/2024:16:14:02 -0500: Schema cache loaded 264 Relations, 221 Relationships, 140 Functions, 15 Domain Representations, 43 Media Type Handlers

---

Nothing to do here since we haven't had reports about parsing being slow. Closing again.