steve-chavez
commented
8 months ago For this I think logging stats of the schema cache load will help. Like so:
06/Feb/2024:23:33:22 -0500: Starting PostgREST 11.2.0 (eaa1d81)...
06/Feb/2024:23:33:22 -0500: Attempting to connect to the database...
06/Feb/2024:23:33:22 -0500: Connection successful
06/Feb/2024:23:33:22 -0500: Admin server listening on port 3001
06/Feb/2024:23:33:22 -0500: Listening on port 3000
06/Feb/2024:23:33:22 -0500: Listening for notifications on the pgrst channel
06/Feb/2024:23:33:22 -0500: Config reloaded
06/Feb/2024:23:33:22 -0500: Schema cache queried in 17.4 milliseconds
06/Feb/2024:23:33:22 -0500: Relations: 264, Relationships: 221, Routines: 140, Domain Representations: 15, Media Type Handlers: 43
06/Feb/2024:23:33:22 -0500: Schema cache loaded in 12.0 millisecondsThat will help users infer if the schema cache queries are taking longer over time. By counting the schema cache items, the user can also infer if the queries are taking longer because of their schema complexity or pg_catalog bloating.
I'll also put a mention about pg_catalog bloating on the docs.
Problem
Having a bloated
pg_depend:Makes the tablesSqlQuery slow:
Execution Time: 4657.589 ms
QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Merge Left Join (cost=8199.72..15348.80 rows=250 width=221) (actual time=4377.186..4657.145 rows=50 loops=1) Merge Cond: (c.relname = cols_agg.table_name) Join Filter: (n.nspname = cols_agg.table_schema) Buffers: shared hit=1695558 -> Merge Left Join (cost=721.01..7842.48 rows=250 width=190) (actual time=3.069..282.889 rows=50 loops=1) Merge Cond: (c.relname = tpks.table_name) Join Filter: (n.nspname = tpks.table_schema) Rows Removed by Join Filter: 1 Buffers: shared hit=337771 -> Nested Loop Left Join (cost=0.83..7121.65 rows=250 width=158) (actual time=0.503..280.251 rows=50 loops=1) Buffers: shared hit=336616 -> Nested Loop (cost=0.54..6909.67 rows=250 width=133) (actual time=0.498..280.116 rows=50 loops=1) Buffers: shared hit=336499 -> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.40..6863.48 rows=258 width=73) (actual time=0.015..279.625 rows=258 loops=1) Filter: ((NOT relispartition) AND (relkind = ANY ('{v,r,m,f,p}'::"char"[]))) Rows Removed by Filter: 377 Buffers: shared hit=335983 -> Index Scan using pg_namespace_oid_index on pg_namespace n (cost=0.14..0.18 rows=1 width=68) (actual time=0.001..0.001 rows=0 loops=258) Index Cond: (oid = c.relnamespace) Filter: (nspname <> ALL ('{pg_catalog,information_schema}'::name[])) Rows Removed by Filter: 1 Buffers: shared hit=516 -> Index Scan using pg_description_o_c_o_index on pg_description d (cost=0.29..0.84 rows=1 width=29) (actual time=0.002..0.002 rows=0 loops=50) Index Cond: ((objoid = c.oid) AND (objsubid = 0)) Buffers: shared hit=117 -> Sort (cost=720.18..720.19 rows=1 width=160) (actual time=2.563..2.584 rows=38 loops=1) Sort Key: tpks.table_name Sort Method: quicksort Memory: 35kB Buffers: shared hit=1155 -> Subquery Scan on tpks (cost=720.14..720.17 rows=1 width=160) (actual time=2.510..2.558 rows=38 loops=1) Buffers: shared hit=1155 -> GroupAggregate (cost=720.14..720.16 rows=1 width=160) (actual time=2.509..2.552 rows=38 loops=1) Group Key: nr_1.nspname, r_1.relname Buffers: shared hit=1155 -> Sort (cost=720.14..720.14 rows=1 width=192) (actual time=2.501..2.516 rows=46 loops=1) Sort Key: nr_1.nspname, r_1.relname Sort Method: quicksort Memory: 35kB Buffers: shared hit=1155 -> Nested Loop (cost=9.37..720.13 rows=1 width=192) (actual time=0.661..2.485 rows=46 loops=1) Buffers: shared hit=1155 -> Nested Loop (cost=7.65..717.29 rows=1 width=164) (actual time=0.634..2.186 rows=46 loops=1) Join Filter: ((c_1.conrelid = r.oid) AND (nr.oid = r.relnamespace)) Rows Removed by Join Filter: 5 Buffers: shared hit=966 -> Nested Loop (cost=7.25..715.75 rows=1 width=172) (actual time=0.617..1.968 rows=48 loops=1) Join Filter: (c_1.connamespace = nc.oid) Rows Removed by Join Filter: 588 Buffers: shared hit=707 -> Nested Loop (cost=7.25..712.27 rows=1 width=176) (actual time=0.609..1.678 rows=48 loops=1) Buffers: shared hit=659 -> Hash Join (cost=6.98..699.01 rows=44 width=232) (actual time=0.600..1.506 rows=55 loops=1) Hash Cond: (nr_1.nspname = nr.nspname) Buffers: shared hit=490 -> ProjectSet (cost=3.60..493.62 rows=16000 width=337) (actual time=0.540..1.417 rows=55 loops=1) Buffers: shared hit=488 -> Nested Loop (cost=3.60..409.54 rows=16 width=219) (actual time=0.401..0.851 rows=45 loops=1) Buffers: shared hit=488 -> Nested Loop (cost=3.45..407.52 rows=16 width=223) (actual time=0.394..0.808 rows=45 loops=1) Buffers: shared hit=475 -> Nested Loop (cost=3.30..404.55 rows=24 width=163) (actual time=0.021..0.717 rows=154 loops=1) Buffers: shared hit=461 -> Seq Scan on pg_constraint c_2 (cost=0.00..16.11 rows=142 width=95) (actual time=0.005..0.079 rows=154 loops=1) Filter: (contype = ANY ('{p,u}'::"char"[])) Rows Removed by Filter: 27 Buffers: shared hit=14 -> Memoize (cost=3.30..4.41 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=154) Cache Key: c_2.conrelid Cache Mode: logical Hits: 54 Misses: 100 Evictions: 0 Overflows: 0 Memory Usage: 17kB Buffers: shared hit=447 -> Bitmap Heap Scan on pg_class r_1 (cost=3.29..4.40 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=100) Recheck Cond: (oid = c_2.conrelid) Filter: (relkind = ANY ('{r,p}'::"char"[])) Heap Blocks: exact=100 Buffers: shared hit=447 -> Bitmap Index Scan on pg_class_oid_index (cost=0.00..3.29 rows=1 width=0) (actual time=0.002..0.002 rows=2 loops=100) Index Cond: (oid = c_2.conrelid) Buffers: shared hit=300 -> Memoize (cost=0.15..0.22 rows=1 width=68) (actual time=0.000..0.000 rows=0 loops=154) Cache Key: r_1.relnamespace Cache Mode: logical Hits: 147 Misses: 7 Evictions: 0 Overflows: 0 Memory Usage: 2kB Buffers: shared hit=14 -> Index Scan using pg_namespace_oid_index on pg_namespace nr_1 (cost=0.14..0.21 rows=1 width=68) (actual time=0.002..0.002 rows=1 loops=7) Index Cond: (oid = r_1.relnamespace) Filter: ((NOT pg_is_other_temp_schema(oid)) AND (nspname <> ALL ('{pg_catalog,information_schema}'::name[]))) Rows Removed by Filter: 0 Buffers: shared hit=14 -> Memoize (cost=0.15..0.20 rows=1 width=4) (actual time=0.001..0.001 rows=1 loops=45) Cache Key: c_2.connamespace Cache Mode: logical Hits: 39 Misses: 6 Evictions: 0 Overflows: 0 Memory Usage: 1kB Buffers: shared hit=13 -> Index Only Scan using pg_namespace_oid_index on pg_namespace nc_1 (cost=0.14..0.19 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=6) Index Cond: (oid = c_2.connamespace) Heap Fetches: 6 Buffers: shared hit=13 -> Hash (cost=2.83..2.83 rows=44 width=68) (actual time=0.054..0.055 rows=15 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 10kB Buffers: shared hit=2 -> Seq Scan on pg_namespace nr (cost=0.00..2.83 rows=44 width=68) (actual time=0.015..0.047 rows=15 loops=1) Filter: (NOT pg_is_other_temp_schema(oid)) Rows Removed by Filter: 78 Buffers: shared hit=2 -> Index Scan using pg_constraint_conname_nsp_index on pg_constraint c_1 (cost=0.27..0.29 rows=1 width=72) (actual time=0.002..0.003 rows=1 loops=55) Index Cond: (conname = c_2.conname) Filter: (contype = 'p'::"char") Rows Removed by Filter: 0 Buffers: shared hit=169 -> Seq Scan on pg_namespace nc (cost=0.00..2.66 rows=66 width=4) (actual time=0.002..0.003 rows=13 loops=48) Buffers: shared hit=48 -> Index Scan using pg_class_relname_nsp_index on pg_class r (cost=0.40..1.53 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=48) Index Cond: (relname = r_1.relname) Filter: (relkind = ANY ('{r,p}'::"char"[])) Buffers: shared hit=259 -> Bitmap Heap Scan on pg_attribute a (cost=1.72..2.84 rows=1 width=70) (actual time=0.005..0.005 rows=1 loops=46) Recheck Cond: ((attrelid = r_1.oid) AND (attnum = ((information_schema._pg_expandarray(c_2.conkey))).x)) Filter: (NOT attisdropped) Heap Blocks: exact=46 Buffers: shared hit=189 -> Bitmap Index Scan on pg_attribute_relid_attnum_index (cost=0.00..1.72 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=46) Index Cond: ((attrelid = r_1.oid) AND (attnum = ((information_schema._pg_expandarray(c_2.conkey))).x)) Buffers: shared hit=138 -> Sort (cost=7478.71..7478.74 rows=11 width=160) (actual time=4374.093..4374.120 rows=20 loops=1) Sort Key: cols_agg.table_name Sort Method: quicksort Memory: 63kB Buffers: shared hit=1357787 -> Subquery Scan on cols_agg (cost=7478.30..7478.52 rows=11 width=160) (actual time=4374.054..4374.095 rows=20 loops=1) Buffers: shared hit=1357787 -> Unique (cost=7478.30..7478.41 rows=11 width=160) (actual time=4374.052..4374.089 rows=20 loops=1) Buffers: shared hit=1357787 -> Sort (cost=7478.30..7478.33 rows=11 width=160) (actual time=4374.051..4374.075 rows=20 loops=1) Sort Key: nc_2.nspname, c_3.relname, (array_agg(ROW(a_1.attname, d_1.description, ((NOT a_1.attnotnull) AND ((t.typtype <> 'd'::"char") OR (NOT t.typnotnull))), CASE WHEN (t.typtype = 'd'::"char") THEN CASE WHEN (nbt.nspname = 'pg_catalog'::name) THEN format_type(t.typbasetype, NULL::integer) ELSE format_type(a_1.atttypid, a_1.atttypmod) END ELSE CASE WHEN (nt.nspname = 'pg_catalog'::name) THEN format_type(a_1.atttypid, NULL::integer) ELSE format_type(a_1.atttypid, a_1.atttypmod) END END, format_type(a_1.atttypid, a_1.atttypmod), information_schema._pg_char_max_length(information_schema._pg_truetypid(a_1.*, t.*), information_schema._pg_truetypmod(a_1.*, t.*)), CASE WHEN (t.typbasetype <> '0'::oid) THEN pg_get_expr(t.typdefaultbin, '0'::oid) WHEN (a_1.attidentity = 'd'::"char") THEN format('nextval(%s)'::text, quote_literal((((seqsch.nspname)::text || '.'::text) || (seqclass.relname)::text))) WHEN (a_1.attgenerated = 's'::"char") THEN NULL::text ELSE pg_get_expr(ad.adbin, ad.adrelid) END, COALESCE(enum_info.vals, '{}'::name[])) ORDER BY ((a_1.attnum)::integer))) Sort Method: quicksort Memory: 63kB Buffers: shared hit=1357787 -> GroupAggregate (cost=7469.04..7478.11 rows=11 width=160) (actual time=4369.662..4374.046 rows=20 loops=1) Group Key: nc_2.nspname, c_3.relname Buffers: shared hit=1357787 -> Sort (cost=7469.04..7469.06 rows=11 width=1161) (actual time=4369.350..4369.409 rows=259 loops=1) Sort Key: nc_2.nspname, c_3.relname Sort Method: quicksort Memory: 189kB Buffers: shared hit=1357787 -> Nested Loop Left Join (cost=532.41..7468.85 rows=11 width=1161) (actual time=22.272..4367.765 rows=259 loops=1) Join Filter: (COALESCE(bt.typname, t.typname) = enum_info.n) Rows Removed by Join Filter: 2072 Buffers: shared hit=1357787 -> Nested Loop Left Join (cost=65.16..6994.40 rows=11 width=1257) (actual time=16.910..4360.260 rows=259 loops=1) Buffers: shared hit=1356999 -> Nested Loop Left Join (cost=65.02..6992.56 rows=11 width=1197) (actual time=16.894..4359.228 rows=259 loops=1) Buffers: shared hit=1356999 -> Nested Loop Left Join (cost=62.73..6955.09 rows=11 width=1133) (actual time=16.879..4354.219 rows=259 loops=1) Buffers: shared hit=1356999 -> Nested Loop Left Join (cost=62.32..6544.64 rows=11 width=1133) (actual time=0.473..41.772 rows=259 loops=1) Join Filter: (t.typtype = 'd'::"char") Buffers: shared hit=9555 -> Nested Loop Left Join (cost=60.53..6512.30 rows=11 width=1005) (actual time=0.467..39.949 rows=259 loops=1) Buffers: shared hit=8778 -> Nested Loop (cost=60.11..6506.87 rows=11 width=1009) (actual time=0.443..36.473 rows=259 loops=1) Buffers: shared hit=7804 -> Nested Loop (cost=59.96..6505.07 rows=11 width=949) (actual time=0.436..35.227 rows=259 loops=1) Buffers: shared hit=7802 -> Nested Loop Left Join (cost=58.98..6482.02 rows=11 width=531) (actual time=0.422..30.487 rows=259 loops=1) Buffers: shared hit=6766 -> Nested Loop Left Join (cost=58.83..6480.14 rows=11 width=495) (actual time=0.415..28.838 rows=259 loops=1) Buffers: shared hit=6503 -> Nested Loop (cost=58.54..6475.86 rows=11 width=470) (actual time=0.409..26.186 rows=259 loops=1) Buffers: shared hit=5985 -> Nested Loop (cost=0.54..6198.89 rows=4 width=132) (actual time=0.390..23.822 rows=20 loops=1) Buffers: shared hit=5852 -> Index Scan using pg_namespace_nspname_index on pg_namespace nc_2 (cost=0.14..2.37 rows=1 width=68) (actual time=0.007..0.008 rows=1 loops=1) Index Cond: (nspname = ANY ('{public}'::name[])) Filter: (NOT pg_is_other_temp_schema(oid)) Buffers: shared hit=2 -> Index Scan using pg_class_relname_nsp_index on pg_class c_3 (cost=0.40..6196.29 rows=23 width=72) (actual time=0.381..23.788 rows=20 loops=1) Index Cond: (relnamespace = nc_2.oid) Filter: (relkind = ANY ('{r,v,f,m,p}'::"char"[])) Rows Removed by Filter: 21 Buffers: shared hit=5850 -> Bitmap Heap Scan on pg_attribute a_1 (cost=58.00..69.14 rows=10 width=342) (actual time=0.025..0.097 rows=13 loops=20) Recheck Cond: ((attrelid = c_3.oid) AND (attnum > 0)) Filter: (NOT attisdropped) Heap Blocks: exact=70 Buffers: shared hit=133 -> Bitmap Index Scan on pg_attribute_relid_attnum_index (cost=0.00..58.00 rows=10 width=0) (actual time=0.016..0.016 rows=14 loops=20) Index Cond: ((attrelid = c_3.oid) AND (attnum > 0)) Buffers: shared hit=60 -> Index Scan using pg_description_o_c_o_index on pg_description d_1 (cost=0.29..0.38 rows=1 width=33) (actual time=0.007..0.007 rows=0 loops=259) Index Cond: ((objoid = a_1.attrelid) AND (objsubid = a_1.attnum)) Buffers: shared hit=518 -> Index Scan using pg_attrdef_adrelid_adnum_index on pg_attrdef ad (cost=0.15..0.17 rows=1 width=38) (actual time=0.004..0.004 rows=0 loops=259) Index Cond: ((adrelid = a_1.attrelid) AND (adnum = a_1.attnum)) Buffers: shared hit=263 -> Bitmap Heap Scan on pg_type t (cost=0.98..2.10 rows=1 width=422) (actual time=0.013..0.013 rows=1 loops=259) Recheck Cond: (oid = a_1.atttypid) Heap Blocks: exact=259 Buffers: shared hit=1036 -> Bitmap Index Scan on pg_type_oid_index (cost=0.00..0.98 rows=1 width=0) (actual time=0.007..0.007 rows=1 loops=259) Index Cond: (oid = a_1.atttypid) Buffers: shared hit=777 -> Memoize (cost=0.15..0.18 rows=1 width=68) (actual time=0.002..0.002 rows=1 loops=259) Cache Key: t.typnamespace Cache Mode: logical Hits: 258 Misses: 1 Evictions: 0 Overflows: 0 Memory Usage: 1kB Buffers: shared hit=2 -> Index Scan using pg_namespace_oid_index on pg_namespace nt (cost=0.14..0.17 rows=1 width=68) (actual time=0.002..0.003 rows=1 loops=1) Index Cond: (oid = t.typnamespace) Buffers: shared hit=2 -> Nested Loop (cost=0.42..0.48 rows=1 width=4) (actual time=0.011..0.011 rows=0 loops=259) Buffers: shared hit=974 -> Index Scan using pg_collation_oid_index on pg_collation co (cost=0.28..0.30 rows=1 width=72) (actual time=0.005..0.006 rows=1 loops=259) Index Cond: (oid = a_1.attcollation) Buffers: shared hit=670 -> Index Scan using pg_namespace_oid_index on pg_namespace nco (cost=0.14..0.17 rows=1 width=68) (actual time=0.005..0.005 rows=0 loops=152) Index Cond: (oid = co.collnamespace) Filter: ((nspname <> 'pg_catalog'::name) OR (co.collname <> 'default'::name)) Rows Removed by Filter: 1 Buffers: shared hit=304 -> Nested Loop (cost=1.79..2.93 rows=1 width=132) (actual time=0.005..0.005 rows=0 loops=259) Buffers: shared hit=777 -> Bitmap Heap Scan on pg_type bt (cost=1.65..2.76 rows=1 width=72) (actual time=0.003..0.003 rows=0 loops=259) Recheck Cond: (t.typbasetype = oid) Buffers: shared hit=777 -> Bitmap Index Scan on pg_type_oid_index (cost=0.00..1.65 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=259) Index Cond: (oid = t.typbasetype) Buffers: shared hit=777 -> Index Scan using pg_namespace_oid_index on pg_namespace nbt (cost=0.14..0.17 rows=1 width=68) (never executed) Index Cond: (oid = bt.typnamespace) -> Index Scan using pg_depend_reference_index on pg_depend dep (cost=0.41..37.30 rows=1 width=12) (actual time=16.646..16.646 rows=0 loops=259) Index Cond: ((refobjid = a_1.attrelid) AND (refobjsubid = a_1.attnum)) Filter: (deptype = 'i'::"char") Rows Removed by Filter: 0 Buffers: shared hit=1347444 -> Bitmap Heap Scan on pg_class seqclass (cost=2.29..3.41 rows=1 width=72) (actual time=0.005..0.005 rows=0 loops=259) Recheck Cond: (oid = dep.objid) -> Bitmap Index Scan on pg_class_oid_index (cost=0.00..2.29 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=259) Index Cond: (oid = dep.objid) -> Index Scan using pg_namespace_oid_index on pg_namespace seqsch (cost=0.14..0.17 rows=1 width=68) (actual time=0.001..0.001 rows=0 loops=259) Index Cond: (oid = seqclass.relnamespace) -> Materialize (cost=467.24..468.59 rows=36 width=96) (actual time=0.021..0.023 rows=8 loops=259) Buffers: shared hit=788 -> Subquery Scan on enum_info (cost=467.24..468.41 rows=36 width=96) (actual time=5.322..5.354 rows=8 loops=1) Buffers: shared hit=788 -> GroupAggregate (cost=467.24..468.05 rows=36 width=160) (actual time=5.321..5.351 rows=8 loops=1) Group Key: n_1.nspname, t_1.typname Buffers: shared hit=788 -> Sort (cost=467.24..467.33 rows=36 width=196) (actual time=5.281..5.287 rows=36 loops=1) Sort Key: n_1.nspname, t_1.typname Sort Method: quicksort Memory: 33kB Buffers: shared hit=788 -> Nested Loop (cost=2.97..466.31 rows=36 width=196) (actual time=0.049..5.245 rows=36 loops=1) Buffers: shared hit=788 -> Nested Loop (cost=2.82..463.82 rows=36 width=136) (actual time=0.037..5.211 rows=36 loops=1) Buffers: shared hit=782 -> Index Scan using pg_enum_typid_sortorder_index on pg_enum e (cost=0.27..430.81 rows=36 width=72) (actual time=0.018..5.139 rows=36 loops=1) Buffers: shared hit=750 -> Memoize (cost=2.56..3.67 rows=1 width=72) (actual time=0.001..0.001 rows=1 loops=36) Cache Key: e.enumtypid Cache Mode: logical Hits: 28 Misses: 8 Evictions: 0 Overflows: 0 Memory Usage: 2kB Buffers: shared hit=32 -> Bitmap Heap Scan on pg_type t_1 (cost=2.55..3.66 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=8) Recheck Cond: (oid = e.enumtypid) Heap Blocks: exact=8 Buffers: shared hit=32 -> Bitmap Index Scan on pg_type_oid_index (cost=0.00..2.55 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=8) Index Cond: (oid = e.enumtypid) Buffers: shared hit=24 -> Memoize (cost=0.15..0.18 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=36) Cache Key: t_1.typnamespace Cache Mode: logical Hits: 33 Misses: 3 Evictions: 0 Overflows: 0 Memory Usage: 1kB Buffers: shared hit=6 -> Index Scan using pg_namespace_oid_index on pg_namespace n_1 (cost=0.14..0.17 rows=1 width=68) (actual time=0.003..0.003 rows=1 loops=3) Index Cond: (oid = t_1.typnamespace) Buffers: shared hit=6 Planning: Buffers: shared hit=221 Planning Time: 7.678 ms Execution Time: 4657.589 ms (279 rows)Same output but on depesz: https://explain.depesz.com/s/7ZKv#html. The main problem is the Index Scan on
pg_depend_reference_index.This is a problem when
statement_timeoutis set low forauthenticator, which leads to a loop of errors like:Also note that for this particular case, vacuum is not working on
pg_depend; this is what's causing the bloat.Solution?
Though the fix here is to clear whatever is holding the vacuum on
pg_depend(in this particular case apg_drop_replication_slot()solved it), could we show a better error message so the problem with the schema cache is obvious?