This adds a new log line that shows each schema cache query time individually, only on
`log-level=debug`. Like so:
```
$ PGRST_LOG_LEVEL=debug postgrest-with-pg-17 -f test/spec/fixtures/load.sql postgrest-run
....
10/Apr/2026:21:48:45 -0500: Schema cache queried in 192.2 milliseconds
10/Apr/2026:21:48:45 -0500: tables: 72.027 ms, keydeps: 20.118 ms, rels: 6.189 ms, funcs: 35.010 ms, comprels: 4.319 ms, dreps: 1.614 ms, mhandlers: 7.419 ms, tzones: 43.025 ms
```
This helps debug specific schema cache queries being slow like on
https://github.com/PostgREST/postgrest/issues/4613#issuecomment-4210191065 and
https://github.com/PostgREST/postgrest/issues/3046#issuecomment-3469059948.
It also closes https://github.com/PostgREST/postgrest/issues/3215,
which main motivation was to find out which query is slow.
Implementation details
---------------------
To time each query inside a transaction in pure SQL, we do:
```sql
-- start timer
select set_config('pgrst.tmp_x', clock_timestamp()::text, false);
-- run the query
select <query>
-- end timer
select set_config('pgrst.tmp_x', (clock_timestamp() - current_setting('pgrst.tmp_x', false)::timestamptz)::text, false);
-- .... repeated for every query
-- at the end we capture all the timings with
select extract('milliseconds' from current_setting('pgrst.tmp_x', false)::interval), extract(..;
```
Considerations
--------------
Only added this on `log-level=debug` because while the queries are fast
and the data is valuable, it triples the amount of queries we run during schema cache refresh,
which could be troublesome on slow networks. It's possible to reduce the
amount of queries by starting and stopping timers in one statement, but
this would still double the amount of queries and makes the code messy,
doesn't seem worth it.
Also it would pollute pg_stat_statements, it's only required to debug certain
extreme cases anyway.
retryingSchemaCacheLoad flushes the pool upon every retry before it starts reloading the schema. This is too early as schema reloading might take some time during which new connections might be acquired. The consequence is that:
* upon successful schema cache reload we might have some connections created with the old schema cache
* we close connections upon each retry and under load we will keep closing and re-opening connections until schema cache load succeeds
This change is to make sure we flush the pool only after successful schema cache querying but before loading (so that connections acquired during loading wait for it and do not interfere with timing the loading process).
DISCLAIMER:
This commit was authored entirely by a human without the assistance of LLMs.
Using debouncer to trigger schema cache loading makes it difficult to understand when exactly it is triggered.
Some helpers are provided for introspecting metrics already (used in JWT cache tests). This change provides facilities to additionally validate emited Observation events.
A new Spec module is also implemented, adding basic tests of schema cache reloading - their main goal is to excercise the new infrastructure.
Right now listening sockets initialization, management and usage is split between App, AppState and Admin modules: they are created in AppState.init and remembered in AppState but used only in App and Admin.
It has several negative consequences:
- sockets are initialized even if not needed (eg. command line invocations like dump-config or dump-schema)
- it is impossible to start listening on a socket after initial schema cache load because it requires AppState
This change decouples listen socket management from AppState. Sockets are created only when needed (ie. not in command line tools invocation) and passed to admin application and to Warp by the App module.
This commit replaces ioRef based implementation of schema cache status tracking to MVar based, so that it is possible to wait for schema cache loading.
Waiting for schema cache loading is necessary to implement zero-downtime upgrades with SO_REUSEPORT, where listening on a socket must wait for schema cache loading.
There is unnecessary coupling between observation messages and emited log entries. This causes schema loading logic to emit redundant events: SchemaCacheSummaryObs and SchemaCacheLoadedObs.
Logically - we want to emit a single event containing both summary and timing information. How it is logged is a different matter and should be decoupled.
This commit
* changes observationMessage function returning Text to observationMessages returning [Text] so that it is possible to return multiple (or zero) messages to log based on an observation event
* Removes SchemaCacheSummaryObs constructor from Observation type and adds summary text to SchemaCacheLoadedObs
Listener has its own backoff logic independent of schema cache loading. It also uses listener delay value to identify its retries and to trigger schema cache reloads upon failures.
If schema cache reloading sets listener delay it might lead to some unexpected reloading loops.
That's especially important in set ups where listener connection points to master and the pool to replica(s).
PoolAcqTimeoutObs is always created with SQL.AcquisitionTimeoutUsageError so the parameter does not provide any useful information.
On the other hand, it complicates debouncing logic in Logger as logWithDebounce has to lazily create the debouncer (which is error prone and hence the logic has a race condition).
This change removes the parameter from PoolAcqTimeoutObs. It is a prerequisite to simplifying logWithDebounce.
Postgrest fails on unsupported pg versions. However before killing
the thread, it continues to print a few more log messages which
were misleading. This commit fixes this by making sure that the
no log message should be printed after the unsupported pg version
observation and kill the thread immediately.
Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
When db-pre-config is accidentally set to a pg reserved word
like "true", it fails with a confusing error. The function
names should be properly quoted to avoid such errors. This commit
resolves this by quoting the pre-config function name.
Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
Changes:
1. Refactoring and some cleanup of JWT handling code:
* Instead of caching AuthResult cache decoded claims (which signature was verified). Validating claims and determining role is done after cache lookup
* Cleaned up API so that usage of it is simplified: lookupJwtCache cache key >>= parseClaims configJwtAud time
* Handling of JwtCacheState initialization and updates of configuration is encapsulated in Auth.JwtCache module
2. Generic high performance (hopefully) scalable, dynamically resizeable cache implementation based on stm, stm-hamt and sieve algorithm. It also integrates with PostgREST measurements infrastructure providing usage stats (ie. hit ratio, evictions count)
It's important for observability to have an historic trace of the pool
size. Currently we expose it on the metrics endpoint, but not all
deployments use it.
This logs the pool size after the successful connection log to make it
more visible:
<timestamp>: Connection Pool initialized with a maximum size of 4 connections
Fixes#3660. Load the config after getting the pg version but before loading the schema.
The regression happened on f09655b.
Also remove schema cache load wrapper and separate db queries in different functions.
Co-authored-by: Laurence Isla <lau.isla.c@gmail.com>
Fixes https://github.com/PostgREST/postgrest/issues/3523.
Now if there's a failure when obtaining the pg version OR schema cache,
we do the same retrying process. This way we don't add two retries.
Refactors and renames the "connectionWorker" to "schemaCacheLoader".
This makes more sense since what we really want is the schema cache,
the version is the pre-requisite for ensuring our
schema cache queries work.
Additionally, we no longer log ` Attempting to connect to the database...`
at startup unnecessarily. This is only logged whenever there's a retry attempt.
Update hasql-notifications to include the fix on
https://github.com/diogob/hasql-notifications/issues/24.
Which now reveals the following error:
```
$ postgrest-with-postgresql-16 --replica -f test/spec/fixtures/load.sql postgrest-run
17/May/2024:18:35:38 -0500: Successfully connected to PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 13.2.0, 64-bit
17/May/2024:18:35:38 -0500: Could not listen for notifications on the "pgrst" channel. ERROR: cannot execute LISTEN during recovery
17/May/2024:18:35:38 -0500: Retrying listening for notifications...
```
This is still not good because the LISTEN channel will be retried
forever without a backoff.
The fatal logic is now inside `usePool`. It centralizes the
logic which is better for Locality of Behavior.
Removes:
- The need to do checkIsFatal on other parts of the code
- SCFatalFail/ConnFatalFail states which are no longer needed.
With this:
- Is no longer necessary to pass observer as an argument
to every function that needs observations.
- We can invoke the observer on every function that uses AppConfig.
However it'd be better to just call the observer in the upper modules
(like on App.hs).
steve-chavez