add: log schema cache queries' timings

[steve-chavez]

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 #4613 (comment) and #3046 (comment). It also closes #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:

-- 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.

TODO

• tests
  • w/wo PGRST_LOG_LEVEL=debug
  • w/wo PGRST_DB_TIMEZONE_ENABLED=false
• docs

[steve-chavez]

Had to change the order of these statements otherwise this test failed

postgrest/test/io/test_io.py

Lines 1247 to 1269 in c9adaed

	def test_schema_cache_load_sleep_logs(defaultenv):
	"""Schema cache load sleep should be reflected in the logged load duration."""
	env = {
	**defaultenv,
	"PGRST_INTERNAL_SCHEMA_CACHE_LOAD_SLEEP": "1000",
	}
	log_pattern = re.compile(r"Schema cache loaded in ([\d.]+) milliseconds")
	with run(env=env, wait_max_seconds=3, no_startup_stdout=False) as postgrest:
	observed_ms = None
	collected = []
	lines = postgrest.read_stdout(nlines=10)
	collected.extend(lines)
	for line in lines:
	match = log_pattern.search(line)
	if match:
	observed_ms = float(match.group(1))
	break
	assert observed_ms is not None
	assert 1000 < observed_ms < 2000