Open sasog23 opened 7 months ago
is this maybe related to postgresql config ?? PostgreSQL 13.14 (Ubuntu 13.14-1.pgdg22.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
@sasog23: Is it perhaps a latency issue?
How long does it take to run SELECT 1
from the "Run SQL" tab of the Hasura Console?
nope, it's ok i've tested this query in pgadmin, and it takes 8+ seconds if i remove "AND ((pgn.nspname='servicedesk'))" and test it, it takes <1s
@sasog23, would you mind getting us an execution plan?
You can run the same query in pgAdmin, but prefix it with EXPLAIN
, and then paste the results here. (Please redact any information you need to.)
Aggregate (cost=584.58..584.59 rows=1 width=32)
-> Subquery Scan on info (cost=578.68..584.54 rows=7 width=152)
-> GroupAggregate (cost=578.68..584.47 rows=7 width=324)
Group Key: pgc.oid, pgn.nspname, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END))
-> Sort (cost=578.68..578.70 rows=7 width=582)
Sort Key: pgc.oid, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END))
-> Nested Loop Left Join (cost=390.47..578.58 rows=7 width=582)
Join Filter: ((nc_1.nspname = pgn.nspname) AND (c_1.relname = pgc.relname))
-> Nested Loop Left Join (cost=349.13..469.16 rows=7 width=519)
Join Filter: (nc.nspname = pgn.nspname)
-> Nested Loop Left Join (cost=346.35..441.12 rows=7 width=487)
-> Nested Loop Left Join (cost=346.07..439.99 rows=1 width=417)
Join Filter: (((ist.event_object_schema)::name = pgn.nspname) AND ((ist.event_object_table)::name = pgc.relname) AND ((ist.trigger_name)::name = pgt.tgname))
-> Nested Loop Left Join (cost=41.62..81.99 rows=1 width=201)
-> Nested Loop (cost=41.34..81.40 rows=1 width=133)
-> Index Scan using pg_namespace_nspname_index on pg_namespace pgn (cost=0.28..2.49 rows=1 width=68)
Index Cond: (nspname = 'servicedesk'::name)
-> Bitmap Heap Scan on pg_class pgc (cost=41.07..78.76 rows=14 width=73)
Recheck Cond: (relnamespace = pgn.oid)
Filter: (relkind = ANY ('{r,v,f,m,p}'::"char"[]))
-> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..41.06 rows=51 width=0)
Index Cond: (relnamespace = pgn.oid)
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pgt (cost=0.28..0.52 rows=7 width=72)
Index Cond: (tgrelid = pgc.oid)
-> Subquery Scan on ist (cost=304.45..357.95 rows=3 width=408)
Filter: ((ist.event_object_schema)::name = 'servicedesk'::name)
-> WindowAgg (cost=304.45..351.43 rows=522 width=888)
-> Sort (cost=304.45..305.75 rows=522 width=438)
Sort Key: ((n.nspname)::information_schema.sql_identifier), ((c_2.relname)::information_schema.sql_identifier), "*VALUES*".column1, (((t_1.tgtype)::integer & 1)), (((t_1.tgtype)::integer & 66)), t_1.tgname
-> Nested Loop (cost=192.35..280.88 rows=522 width=438)
Join Filter: (((t_1.tgtype)::integer & "*VALUES*".column1) <> 0)
-> Hash Join (cost=192.35..265.12 rows=175 width=330)
Hash Cond: (t_1.tgrelid = c_2.oid)
-> Seq Scan on pg_trigger t_1 (cost=0.00..69.62 rows=374 width=202)
Filter: (NOT tgisinternal)
-> Hash (cost=178.52..178.52 rows=1106 width=136)
-> Hash Join (cost=22.81..178.52 rows=1106 width=136)
Hash Cond: (c_2.relnamespace = n.oid)
-> Seq Scan on pg_class c_2 (cost=0.00..151.32 rows=1659 width=76)
Filter: (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'INSERT, UPDATE, REFERENCES'::text))
-> Hash (cost=17.29..17.29 rows=442 width=68)
-> Seq Scan on pg_namespace n (cost=0.00..17.29 rows=442 width=68)
Filter: (NOT pg_is_other_temp_schema(oid))
-> Materialize (cost=0.00..0.05 rows=3 width=36)
-> Values Scan on "*VALUES*" (cost=0.00..0.04 rows=3 width=36)
-> Index Scan using pg_attribute_relid_attnum_index on pg_attribute pga (cost=0.29..1.06 rows=7 width=70)
Index Cond: (attrelid = pgc.oid)
-> Nested Loop Left Join (cost=2.77..3.99 rows=1 width=224)
-> Nested Loop (cost=2.22..3.36 rows=1 width=228)
-> Nested Loop (cost=1.95..3.03 rows=1 width=627)
-> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.28..0.44 rows=1 width=76)
Index Cond: (relname = pgc.relname)
Filter: (relkind = ANY ('{r,v,m,f,p}'::"char"[]))
-> Nested Loop (cost=1.67..2.58 rows=1 width=571)
-> Nested Loop Left Join (cost=1.39..2.25 rows=1 width=503)
-> Nested Loop Left Join (cost=1.11..1.95 rows=1 width=294)
Join Filter: (t.typtype = 'd'::"char")
-> Nested Loop (cost=0.56..1.31 rows=1 width=160)
-> Index Scan using pg_attribute_relid_attnam_index on pg_attribute a (cost=0.29..1.01 rows=1 width=80)
Index Cond: ((attrelid = c.oid) AND (attname = pga.attname))
Filter: ((NOT attisdropped) AND (attnum > 0) AND (pg_has_role(c.relowner, 'USAGE'::text) OR has_column_privilege(c.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text)))
-> Index Scan using pg_type_oid_index on pg_type t (cost=0.28..0.30 rows=1 width=84)
Index Cond: (oid = a.atttypid)
-> Nested Loop (cost=0.55..0.63 rows=1 width=138)
-> Index Scan using pg_type_oid_index on pg_type bt (cost=0.28..0.33 rows=1 width=78)
Index Cond: (oid = t.typbasetype)
-> Index Scan using pg_namespace_oid_index on pg_namespace nbt (cost=0.28..0.30 rows=1 width=68)
Index Cond: (oid = bt.typnamespace)
-> Index Scan using pg_attrdef_adrelid_adnum_index on pg_attrdef ad (cost=0.28..0.30 rows=1 width=211)
Index Cond: ((adrelid = a.attrelid) AND (adnum = a.attnum))
-> Index Scan using pg_namespace_oid_index on pg_namespace nc (cost=0.28..0.32 rows=1 width=68)
Index Cond: (oid = c.relnamespace)
Filter: ((NOT pg_is_other_temp_schema(oid)) AND (nspname = 'servicedesk'::name))
-> Index Scan using pg_namespace_oid_index on pg_namespace nt (cost=0.28..0.30 rows=1 width=68)
Index Cond: (oid = t.typnamespace)
-> Nested Loop (cost=0.55..0.62 rows=1 width=4)
-> Index Scan using pg_collation_oid_index on pg_collation co (cost=0.28..0.30 rows=1 width=72)
Index Cond: (oid = a.attcollation)
-> Index Scan using pg_namespace_oid_index on pg_namespace nco (cost=0.28..0.32 rows=1 width=68)
Index Cond: (oid = co.collnamespace)
Filter: ((nspname <> 'pg_catalog'::name) OR (co.collname <> 'default'::name))
-> Materialize (cost=41.34..109.21 rows=1 width=160)
-> Nested Loop (cost=41.34..109.21 rows=1 width=160)
-> Index Scan using pg_namespace_nspname_index on pg_namespace nc_1 (cost=0.28..2.50 rows=1 width=68)
Index Cond: (nspname = 'servicedesk'::name)
Filter: (NOT pg_is_other_temp_schema(oid))
-> Bitmap Heap Scan on pg_class c_1 (cost=41.07..80.10 rows=2 width=76)
Recheck Cond: (relnamespace = nc_1.oid)
Filter: ((relkind = ANY ('{v,m}'::"char"[])) AND (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'SELECT, INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'SELECT, INSERT, UPDATE, REFERENCES'::text)))
-> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..41.06 rows=51 width=0)
Index Cond: (relnamespace = nc_1.oid)
SubPlan 1
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger (cost=0.28..8.84 rows=1 width=0)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 81) = 81)
SubPlan 2
-> Seq Scan on pg_trigger pg_trigger_1 (cost=0.00..85.84 rows=11 width=4)
Filter: (((tgtype)::integer & 81) = 81)
SubPlan 3
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_2 (cost=0.28..8.84 rows=1 width=0)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 73) = 73)
SubPlan 4
-> Seq Scan on pg_trigger pg_trigger_3 (cost=0.00..85.84 rows=11 width=4)
Filter: (((tgtype)::integer & 73) = 73)
SubPlan 5
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_4 (cost=0.28..8.84 rows=1 width=0)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 69) = 69)
SubPlan 6
-> Seq Scan on pg_trigger pg_trigger_5 (cost=0.00..85.84 rows=11 width=4)
Filter: (((tgtype)::integer & 69) = 69)
We're seeing quite a different analysis here compared to local testing. It could be that indices are misbehaving somehow.
I suggest running VACUUM ANALYZE
on the database and seeing if this helps.
nope, same result 8+seconds
EXPLAIN analyze...result
Aggregate (cost=585.41..585.42 rows=1 width=32) (actual time=8303.574..8303.598 rows=1 loops=1)
-> Subquery Scan on info (cost=579.51..585.37 rows=7 width=152) (actual time=8148.891..8303.426 rows=56 loops=1)
-> GroupAggregate (cost=579.51..585.30 rows=7 width=324) (actual time=8148.886..8303.367 rows=56 loops=1)
Group Key: pgc.oid, pgn.nspname, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END))
-> Sort (cost=579.51..579.52 rows=7 width=582) (actual time=8145.496..8149.336 rows=12889 loops=1)
Sort Key: pgc.oid, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END))
Sort Method: external merge Disk: 7568kB
-> Nested Loop Left Join (cost=391.06..579.41 rows=7 width=582) (actual time=22.607..8124.999 rows=12889 loops=1)
Join Filter: ((nc_1.nspname = pgn.nspname) AND (c_1.relname = pgc.relname))
Rows Removed by Join Filter: 12880
-> Nested Loop Left Join (cost=349.72..469.96 rows=7 width=519) (actual time=21.839..8118.684 rows=12889 loops=1)
Join Filter: (nc.nspname = pgn.nspname)
-> Nested Loop Left Join (cost=346.95..442.02 rows=7 width=487) (actual time=21.815..7956.930 rows=12889 loops=1)
-> Nested Loop Left Join (cost=346.67..440.91 rows=1 width=417) (actual time=21.804..7947.610 rows=428 loops=1)
Join Filter: (((ist.event_object_schema)::name = pgn.nspname) AND ((ist.event_object_table)::name = pgc.relname) AND ((ist.trigger_name)::name = pgt.tgname))
Rows Removed by Join Filter: 43491
-> Nested Loop Left Join (cost=41.62..82.00 rows=1 width=201) (actual time=0.132..1.144 rows=400 loops=1)
-> Nested Loop (cost=41.34..81.41 rows=1 width=133) (actual time=0.123..0.407 rows=56 loops=1)
-> Index Scan using pg_namespace_nspname_index on pg_namespace pgn (cost=0.28..2.49 rows=1 width=68) (actual time=0.012..0.014 rows=1 loops=1)
Index Cond: (nspname = 'servicedesk'::name)
-> Bitmap Heap Scan on pg_class pgc (cost=41.06..78.78 rows=14 width=73) (actual time=0.109..0.359 rows=56 loops=1)
Recheck Cond: (relnamespace = pgn.oid)
Filter: (relkind = ANY ('{r,v,f,m,p}'::"char"[]))
Rows Removed by Filter: 163
Heap Blocks: exact=41
-> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..41.06 rows=52 width=0) (actual time=0.095..0.095 rows=219 loops=1)
Index Cond: (relnamespace = pgn.oid)
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pgt (cost=0.28..0.52 rows=7 width=72) (actual time=0.006..0.010 rows=7 loops=56)
Index Cond: (tgrelid = pgc.oid)
-> Subquery Scan on ist (cost=305.05..358.86 rows=3 width=408) (actual time=10.988..19.854 rows=109 loops=400)
Filter: ((ist.event_object_schema)::name = 'servicedesk'::name)
Rows Removed by Filter: 353
-> WindowAgg (cost=305.05..352.30 rows=525 width=888) (actual time=0.054..19.775 rows=462 loops=400)
-> Sort (cost=305.05..306.36 rows=525 width=438) (actual time=0.006..0.038 rows=462 loops=400)
Sort Key: ((n.nspname)::information_schema.sql_identifier), ((c_2.relname)::information_schema.sql_identifier), "*VALUES*".column1, (((t_1.tgtype)::integer & 1)), (((t_1.tgtype)::integer & 66)), t_1.tgname
Sort Method: quicksort Memory: 263kB
-> Nested Loop (cost=192.54..281.33 rows=525 width=438) (actual time=1.393..1.959 rows=462 loops=1)
Join Filter: (((t_1.tgtype)::integer & "*VALUES*".column1) <> 0)
Rows Removed by Join Filter: 666
-> Hash Join (cost=192.54..265.47 rows=176 width=330) (actual time=1.387..1.742 rows=376 loops=1)
Hash Cond: (t_1.tgrelid = c_2.oid)
-> Seq Scan on pg_trigger t_1 (cost=0.00..69.76 rows=376 width=202) (actual time=0.004..0.272 rows=376 loops=1)
Filter: (NOT tgisinternal)
Rows Removed by Filter: 1800
-> Hash (cost=178.72..178.72 rows=1106 width=136) (actual time=1.360..1.362 rows=2357 loops=1)
Buckets: 4096 (originally 2048) Batches: 1 (originally 1) Memory Usage: 419kB
-> Hash Join (cost=23.06..178.72 rows=1106 width=136) (actual time=0.157..0.962 rows=2357 loops=1)
Hash Cond: (c_2.relnamespace = n.oid)
-> Seq Scan on pg_class c_2 (cost=0.00..151.28 rows=1659 width=76) (actual time=0.005..0.476 rows=2357 loops=1)
Filter: (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'INSERT, UPDATE, REFERENCES'::text))
-> Hash (cost=17.44..17.44 rows=450 width=68) (actual time=0.135..0.136 rows=47 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 13kB
-> Seq Scan on pg_namespace n (cost=0.00..17.44 rows=450 width=68) (actual time=0.004..0.126 rows=47 loops=1)
Filter: (NOT pg_is_other_temp_schema(oid))
Rows Removed by Filter: 628
-> Materialize (cost=0.00..0.05 rows=3 width=36) (actual time=0.000..0.000 rows=3 loops=376)
-> Values Scan on "*VALUES*" (cost=0.00..0.04 rows=3 width=36) (actual time=0.002..0.002 rows=3 loops=1)
-> Index Scan using pg_attribute_relid_attnum_index on pg_attribute pga (cost=0.29..1.04 rows=7 width=70) (actual time=0.004..0.016 rows=30 loops=428)
Index Cond: (attrelid = pgc.oid)
-> Nested Loop Left Join (cost=2.77..3.98 rows=1 width=224) (actual time=0.011..0.012 rows=1 loops=12889)
-> Nested Loop (cost=2.22..3.35 rows=1 width=228) (actual time=0.010..0.011 rows=1 loops=12889)
-> Nested Loop (cost=1.95..3.01 rows=1 width=627) (actual time=0.007..0.008 rows=1 loops=12889)
-> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.28..0.44 rows=1 width=76) (actual time=0.001..0.001 rows=1 loops=12889)
Index Cond: (relname = pgc.relname)
Filter: (relkind = ANY ('{r,v,m,f,p}'::"char"[]))
-> Nested Loop (cost=1.67..2.56 rows=1 width=571) (actual time=0.005..0.006 rows=1 loops=13618)
-> Nested Loop Left Join (cost=1.39..2.23 rows=1 width=503) (actual time=0.004..0.005 rows=1 loops=13618)
-> Nested Loop Left Join (cost=1.11..1.93 rows=1 width=294) (actual time=0.003..0.004 rows=1 loops=13618)
Join Filter: (t.typtype = 'd'::"char")
-> Nested Loop (cost=0.56..1.29 rows=1 width=160) (actual time=0.002..0.003 rows=1 loops=13618)
-> Index Scan using pg_attribute_relid_attnam_index on pg_attribute a (cost=0.29..0.99 rows=1 width=80) (actual time=0.001..0.001 rows=1 loops=13618)
Index Cond: ((attrelid = c.oid) AND (attname = pga.attname))
Filter: ((NOT attisdropped) AND (attnum > 0) AND (pg_has_role(c.relowner, 'USAGE'::text) OR has_column_privilege(c.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text)))
Rows Removed by Filter: 0
-> Index Scan using pg_type_oid_index on pg_type t (cost=0.28..0.30 rows=1 width=84) (actual time=0.001..0.001 rows=1 loops=10241)
Index Cond: (oid = a.atttypid)
-> Nested Loop (cost=0.55..0.63 rows=1 width=138) (actual time=0.001..0.001 rows=0 loops=10241)
-> Index Scan using pg_type_oid_index on pg_type bt (cost=0.28..0.33 rows=1 width=78) (actual time=0.001..0.001 rows=0 loops=10241)
Index Cond: (oid = t.typbasetype)
-> Index Scan using pg_namespace_oid_index on pg_namespace nbt (cost=0.28..0.30 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=7)
Index Cond: (oid = bt.typnamespace)
-> Index Scan using pg_attrdef_adrelid_adnum_index on pg_attrdef ad (cost=0.28..0.30 rows=1 width=211) (actual time=0.001..0.001 rows=0 loops=10241)
Index Cond: ((adrelid = a.attrelid) AND (adnum = a.attnum))
-> Index Scan using pg_namespace_oid_index on pg_namespace nc (cost=0.28..0.32 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=10241)
Index Cond: (oid = c.relnamespace)
Filter: ((NOT pg_is_other_temp_schema(oid)) AND (nspname = 'servicedesk'::name))
Rows Removed by Filter: 0
-> Index Scan using pg_namespace_oid_index on pg_namespace nt (cost=0.28..0.30 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=10051)
Index Cond: (oid = t.typnamespace)
-> Nested Loop (cost=0.55..0.62 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=10051)
-> Index Scan using pg_collation_oid_index on pg_collation co (cost=0.28..0.30 rows=1 width=72) (actual time=0.001..0.001 rows=0 loops=10051)
Index Cond: (oid = a.attcollation)
-> Index Scan using pg_namespace_oid_index on pg_namespace nco (cost=0.28..0.32 rows=1 width=68) (actual time=0.001..0.001 rows=0 loops=1151)
Index Cond: (oid = co.collnamespace)
Filter: ((nspname <> 'pg_catalog'::name) OR (co.collname <> 'default'::name))
Rows Removed by Filter: 1
-> Materialize (cost=41.33..109.24 rows=1 width=160) (actual time=0.000..0.000 rows=1 loops=12889)
-> Nested Loop (cost=41.33..109.24 rows=1 width=160) (actual time=0.752..0.770 rows=1 loops=1)
-> Index Scan using pg_namespace_nspname_index on pg_namespace nc_1 (cost=0.28..2.50 rows=1 width=68) (actual time=0.006..0.006 rows=1 loops=1)
Index Cond: (nspname = 'servicedesk'::name)
Filter: (NOT pg_is_other_temp_schema(oid))
-> Bitmap Heap Scan on pg_class c_1 (cost=41.06..80.14 rows=2 width=76) (actual time=0.112..0.124 rows=1 loops=1)
Recheck Cond: (relnamespace = nc_1.oid)
Filter: ((relkind = ANY ('{v,m}'::"char"[])) AND (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'SELECT, INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'SELECT, INSERT, UPDATE, REFERENCES'::text)))
Rows Removed by Filter: 218
Heap Blocks: exact=41
-> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..41.06 rows=52 width=0) (actual time=0.066..0.066 rows=219 loops=1)
Index Cond: (relnamespace = nc_1.oid)
SubPlan 1
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger (cost=0.28..8.84 rows=1 width=0) (actual time=0.006..0.007 rows=0 loops=1)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 81) = 81)
SubPlan 2
-> Seq Scan on pg_trigger pg_trigger_1 (cost=0.00..86.08 rows=11 width=4) (never executed)
Filter: (((tgtype)::integer & 81) = 81)
SubPlan 3
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_2 (cost=0.28..8.84 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 73) = 73)
SubPlan 4
-> Seq Scan on pg_trigger pg_trigger_3 (cost=0.00..86.08 rows=11 width=4) (never executed)
Filter: (((tgtype)::integer & 73) = 73)
SubPlan 5
-> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_4 (cost=0.28..8.84 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1)
Index Cond: (tgrelid = c_1.oid)
Filter: (((tgtype)::integer & 69) = 69)
SubPlan 6
-> Seq Scan on pg_trigger pg_trigger_5 (cost=0.00..86.08 rows=11 width=4) (never executed)
Filter: (((tgtype)::integer & 69) = 69)
Planning Time: 5.782 ms
Execution Time: 8304.939 ms
EXPLAIN (ANALYZE, BUFFERS)
Aggregate (cost=587.91..587.92 rows=1 width=32) (actual time=8830.090..8830.115 rows=1 loops=1) Buffers: shared hit=1976728, temp read=954 written=956 -> Subquery Scan on info (cost=582.01..587.87 rows=7 width=152) (actual time=8677.645..8829.953 rows=57 loops=1) Buffers: shared hit=1976728, temp read=954 written=956 -> GroupAggregate (cost=582.01..587.80 rows=7 width=324) (actual time=8677.639..8829.898 rows=57 loops=1) Group Key: pgc.oid, pgn.nspname, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END)) Buffers: shared hit=1976728, temp read=954 written=956 -> Sort (cost=582.01..582.03 rows=7 width=582) (actual time=8674.185..8677.986 rows=12994 loops=1) Sort Key: pgc.oid, pgc.relname, (CASE WHEN (pgc.relkind = 'r'::"char") THEN 'TABLE'::text WHEN (pgc.relkind = 'f'::"char") THEN 'FOREIGN TABLE'::text WHEN (pgc.relkind = 'v'::"char") THEN 'VIEW'::text WHEN (pgc.relkind = 'm'::"char") THEN 'MATERIALIZED VIEW'::text WHEN (pgc.relkind = 'p'::"char") THEN 'PARTITIONED TABLE'::text ELSE NULL::text END), (ROW(nc_1.nspname, c_1.relname, CASE WHEN pg_has_role(c_1.relowner, 'USAGE'::text) THEN pg_get_viewdef(c_1.oid) ELSE NULL::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 20) = 20) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN ((pg_relation_is_updatable((c_1.oid)::regclass, false) & 8) = 8) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 1 or hashed SubPlan 2) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 3 or hashed SubPlan 4) THEN 'YES'::text ELSE 'NO'::text END, CASE WHEN (alternatives: SubPlan 5 or hashed SubPlan 6) THEN 'YES'::text ELSE 'NO'::text END)) Sort Method: external merge Disk: 7632kB Buffers: shared hit=1949284, temp read=954 written=956 -> Nested Loop Left Join (cost=390.76..581.91 rows=7 width=582) (actual time=26.289..8657.516 rows=12994 loops=1) Join Filter: ((nc_1.nspname = pgn.nspname) AND (c_1.relname = pgc.relname)) Rows Removed by Join Filter: 12985 Buffers: shared hit=1949284 -> Nested Loop Left Join (cost=351.33..473.29 rows=7 width=519) (actual time=25.427..8650.930 rows=12994 loops=1) Join Filter: (nc.nspname = pgn.nspname) Buffers: shared hit=1949109 -> Nested Loop Left Join (cost=348.56..445.29 rows=7 width=487) (actual time=25.394..8482.494 rows=12994 loops=1) Buffers: shared hit=1706146 -> Nested Loop Left Join (cost=348.27..444.16 rows=1 width=417) (actual time=25.372..8472.721 rows=429 loops=1) Join Filter: (((ist.event_object_schema)::name = pgn.nspname) AND ((ist.event_object_table)::name = pgc.relname) AND ((ist.trigger_name)::name = pgt.tgname)) Rows Removed by Join Filter: 43600 Buffers: shared hit=1697714 -> Nested Loop Left Join (cost=39.72..81.12 rows=1 width=201) (actual time=0.162..1.177 rows=401 loops=1) Buffers: shared hit=329 -> Nested Loop (cost=39.44..80.53 rows=1 width=133) (actual time=0.147..0.414 rows=57 loops=1) Buffers: shared hit=65 -> Index Scan using pg_namespace_nspname_index on pg_namespace pgn (cost=0.28..2.49 rows=1 width=68) (actual time=0.008..0.009 rows=1 loops=1) Index Cond: (nspname = 'servicedesk'::name) Buffers: shared hit=3 -> Bitmap Heap Scan on pg_class pgc (cost=39.16..77.90 rows=14 width=73) (actual time=0.137..0.372 rows=57 loops=1) Recheck Cond: (relnamespace = pgn.oid) Filter: (relkind = ANY ('{r,v,f,m,p}'::"char"[])) Rows Removed by Filter: 163 Heap Blocks: exact=44 Buffers: shared hit=62 -> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..39.16 rows=53 width=0) (actual time=0.127..0.128 rows=220 loops=1) Index Cond: (relnamespace = pgn.oid) Buffers: shared hit=18 -> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pgt (cost=0.28..0.52 rows=7 width=72) (actual time=0.005..0.009 rows=7 loops=57) Index Cond: (tgrelid = pgc.oid) Buffers: shared hit=264 -> Subquery Scan on ist (cost=308.56..362.98 rows=3 width=408) (actual time=11.891..21.113 rows=109 loops=401) Filter: ((ist.event_object_schema)::name = 'servicedesk'::name) Rows Removed by Filter: 361 Buffers: shared hit=1697385 -> WindowAgg (cost=308.56..356.35 rows=531 width=888) (actual time=0.055..21.026 rows=470 loops=401) Buffers: shared hit=1697385 -> Sort (cost=308.56..309.88 rows=531 width=438) (actual time=0.005..0.043 rows=470 loops=401) Sort Key: ((n.nspname)::information_schema.sql_identifier), ((c_2.relname)::information_schema.sql_identifier), "VALUES".column1, (((t_1.tgtype)::integer & 1)), (((t_1.tgtype)::integer & 66)), t_1.tgname Sort Method: quicksort Memory: 267kB Buffers: shared hit=115 -> Nested Loop (cost=195.46..284.52 rows=531 width=438) (actual time=1.300..1.910 rows=470 loops=1) Join Filter: (((t_1.tgtype)::integer & "VALUES".column1) <> 0) Rows Removed by Join Filter: 679 Buffers: shared hit=115 -> Hash Join (cost=195.46..268.49 rows=178 width=330) (actual time=1.295..1.693 rows=383 loops=1) Hash Cond: (t_1.tgrelid = c_2.oid) Buffers: shared hit=115 -> Seq Scan on pg_trigger t_1 (cost=0.00..69.83 rows=379 width=202) (actual time=0.011..0.326 rows=383 loops=1) Filter: (NOT tgisinternal) Rows Removed by Filter: 1872 Buffers: shared hit=48 -> Hash (cost=181.39..181.39 rows=1125 width=136) (actual time=1.278..1.281 rows=2397 loops=1) Buckets: 4096 (originally 2048) Batches: 1 (originally 1) Memory Usage: 426kB Buffers: shared hit=67 -> Hash Join (cost=23.06..181.39 rows=1125 width=136) (actual time=0.165..0.991 rows=2397 loops=1) Hash Cond: (c_2.relnamespace = n.oid) Buffers: shared hit=67 -> Seq Scan on pg_class c_2 (cost=0.00..153.88 rows=1687 width=76) (actual time=0.002..0.495 rows=2397 loops=1) Filter: (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'INSERT, UPDATE, REFERENCES'::text)) Buffers: shared hit=58 -> Hash (cost=17.44..17.44 rows=450 width=68) (actual time=0.160..0.160 rows=49 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 13kB Buffers: shared hit=9 -> Seq Scan on pg_namespace n (cost=0.00..17.44 rows=450 width=68) (actual time=0.003..0.153 rows=49 loops=1) Filter: (NOT pg_is_other_temp_schema(oid)) Rows Removed by Filter: 640 Buffers: shared hit=9 -> Materialize (cost=0.00..0.05 rows=3 width=36) (actual time=0.000..0.000 rows=3 loops=383) -> Values Scan on "VALUES" (cost=0.00..0.04 rows=3 width=36) (actual time=0.001..0.002 rows=3 loops=1) -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute pga (cost=0.29..1.06 rows=7 width=70) (actual time=0.004..0.017 rows=30 loops=429) Index Cond: (attrelid = pgc.oid) Buffers: shared hit=8432 -> Nested Loop Left Join (cost=2.77..3.99 rows=1 width=224) (actual time=0.012..0.013 rows=1 loops=12994) Buffers: shared hit=242963 -> Nested Loop (cost=2.22..3.35 rows=1 width=228) (actual time=0.011..0.011 rows=1 loops=12994) Buffers: shared hit=218051 -> Nested Loop (cost=1.95..3.02 rows=1 width=627) (actual time=0.007..0.008 rows=1 loops=12994) Buffers: shared hit=187588 -> Index Scan using pg_class_relname_nsp_index on pg_class c (cost=0.28..0.44 rows=1 width=76) (actual time=0.001..0.001 rows=1 loops=12994) Index Cond: (relname = pgc.relname) Filter: (relkind = ANY ('{r,v,m,f,p}'::"char"[])) Buffers: shared hit=39712 -> Nested Loop (cost=1.67..2.58 rows=1 width=571) (actual time=0.005..0.006 rows=1 loops=13724) Buffers: shared hit=147876 -> Nested Loop Left Join (cost=1.39..2.25 rows=1 width=503) (actual time=0.004..0.005 rows=1 loops=13724) Buffers: shared hit=116856 -> Nested Loop Left Join (cost=1.11..1.94 rows=1 width=294) (actual time=0.003..0.004 rows=1 loops=13724) Join Filter: (t.typtype = 'd'::"char") Buffers: shared hit=92570 -> Nested Loop (cost=0.56..1.30 rows=1 width=160) (actual time=0.002..0.003 rows=1 loops=13724) Buffers: shared hit=71862 -> Index Scan using pg_attribute_relid_attnam_index on pg_attribute a (cost=0.29..1.00 rows=1 width=80) (actual time=0.001..0.001 rows=1 loops=13724) Index Cond: ((attrelid = c.oid) AND (attname = pga.attname)) Filter: ((NOT attisdropped) AND (attnum > 0) AND (pg_has_role(c.relowner, 'USAGE'::text) OR has_column_privilege(c.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text))) Rows Removed by Filter: 0 Buffers: shared hit=40842 -> Index Scan using pg_type_oid_index on pg_type t (cost=0.28..0.30 rows=1 width=84) (actual time=0.001..0.001 rows=1 loops=10340) Index Cond: (oid = a.atttypid) Buffers: shared hit=31020 -> Nested Loop (cost=0.55..0.63 rows=1 width=138) (actual time=0.001..0.001 rows=0 loops=10340) Buffers: shared hit=20708 -> Index Scan using pg_type_oid_index on pg_type bt (cost=0.28..0.33 rows=1 width=78) (actual time=0.001..0.001 rows=0 loops=10340) Index Cond: (oid = t.typbasetype) Buffers: shared hit=20687 -> Index Scan using pg_namespace_oid_index on pg_namespace nbt (cost=0.28..0.30 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=7) Index Cond: (oid = bt.typnamespace) Buffers: shared hit=21 -> Index Scan using pg_attrdef_adrelid_adnum_index on pg_attrdef ad (cost=0.28..0.30 rows=1 width=211) (actual time=0.001..0.001 rows=0 loops=10340) Index Cond: ((adrelid = a.attrelid) AND (adnum = a.attnum)) Buffers: shared hit=24286 -> Index Scan using pg_namespace_oid_index on pg_namespace nc (cost=0.28..0.32 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=10340) Index Cond: (oid = c.relnamespace) Filter: ((NOT pg_is_other_temp_schema(oid)) AND (nspname = 'servicedesk'::name)) Rows Removed by Filter: 0 Buffers: shared hit=31020 -> Index Scan using pg_namespace_oid_index on pg_namespace nt (cost=0.28..0.30 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=10150) Index Cond: (oid = t.typnamespace) Buffers: shared hit=30450 -> Nested Loop (cost=0.55..0.62 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=10150) Buffers: shared hit=24912 -> Index Scan using pg_collation_oid_index on pg_collation co (cost=0.28..0.30 rows=1 width=72) (actual time=0.001..0.001 rows=0 loops=10150) Index Cond: (oid = a.attcollation) Buffers: shared hit=21453 -> Index Scan using pg_namespace_oid_index on pg_namespace nco (cost=0.28..0.32 rows=1 width=68) (actual time=0.001..0.001 rows=0 loops=1153) Index Cond: (oid = co.collnamespace) Filter: ((nspname <> 'pg_catalog'::name) OR (co.collname <> 'default'::name)) Rows Removed by Filter: 1 Buffers: shared hit=3459 -> Materialize (cost=39.43..108.42 rows=1 width=160) (actual time=0.000..0.000 rows=1 loops=12994) Buffers: shared hit=175 -> Nested Loop (cost=39.43..108.41 rows=1 width=160) (actual time=0.835..0.864 rows=1 loops=1) Buffers: shared hit=175 -> Index Scan using pg_namespace_nspname_index on pg_namespace nc_1 (cost=0.28..2.50 rows=1 width=68) (actual time=0.005..0.006 rows=1 loops=1) Index Cond: (nspname = 'servicedesk'::name) Filter: (NOT pg_is_other_temp_schema(oid)) Buffers: shared hit=3 -> Bitmap Heap Scan on pg_class c_1 (cost=39.16..79.29 rows=2 width=76) (actual time=0.130..0.153 rows=1 loops=1) Recheck Cond: (relnamespace = nc_1.oid) Filter: ((relkind = ANY ('{v,m}'::"char"[])) AND (pg_has_role(relowner, 'USAGE'::text) OR has_table_privilege(oid, 'SELECT, INSERT, UPDATE, DELETE, TRUNCATE, REFERENCES, TRIGGER'::text) OR has_any_column_privilege(oid, 'SELECT, INSERT, UPDATE, REFERENCES'::text))) Rows Removed by Filter: 219 Heap Blocks: exact=44 Buffers: shared hit=62 -> Bitmap Index Scan on pg_class_relname_nsp_index (cost=0.00..39.16 rows=53 width=0) (actual time=0.070..0.070 rows=220 loops=1) Index Cond: (relnamespace = nc_1.oid) Buffers: shared hit=18 SubPlan 1 -> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger (cost=0.28..8.85 rows=1 width=0) (actual time=0.004..0.004 rows=0 loops=1) Index Cond: (tgrelid = c_1.oid) Filter: (((tgtype)::integer & 81) = 81) Buffers: shared hit=2 SubPlan 2 -> Seq Scan on pg_trigger pg_trigger_1 (cost=0.00..86.20 rows=11 width=4) (never executed) Filter: (((tgtype)::integer & 81) = 81) SubPlan 3 -> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_2 (cost=0.28..8.85 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1) Index Cond: (tgrelid = c_1.oid) Filter: (((tgtype)::integer & 73) = 73) Buffers: shared hit=2 SubPlan 4 -> Seq Scan on pg_trigger pg_trigger_3 (cost=0.00..86.20 rows=11 width=4) (never executed) Filter: (((tgtype)::integer & 73) = 73) SubPlan 5 -> Index Scan using pg_trigger_tgrelid_tgname_index on pg_trigger pg_trigger_4 (cost=0.28..8.85 rows=1 width=0) (actual time=0.001..0.001 rows=0 loops=1) Index Cond: (tgrelid = c_1.oid) Filter: (((tgtype)::integer & 69) = 69) Buffers: shared hit=2 SubPlan 6 -> Seq Scan on pg_trigger pg_trigger_5 (cost=0.00..86.20 rows=11 width=4) (never executed) Filter: (((tgtype)::integer & 69) = 69) Planning: Buffers: shared hit=256 Planning Time: 7.105 ms Execution Time: 8831.508 ms
what helps is
SET enable_nestloop = off;
query takes less then 2seconds
but it's probably not a good idea to change this flag
upgrade to "PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit" solved the problem
after a few weeks the problem reappeared
slow query is only the first one
after executing bellow script, the "response time" of the query went back to "normal"...less than 1s
DO $$ DECLARE r RECORD; BEGIN FOR r IN (SELECT nspname FROM pg_namespace WHERE nspname LIKE 'pg_temp%' OR nspname LIKE 'pg_toast_temp%') LOOP EXECUTE 'DROP SCHEMA IF EXISTS ' || quote_ident(r.nspname) || ' CASCADE'; END LOOP; END $$;
Version Information
Server Version: 2.37.0 CLI Version (for CLI related issue):
Environment OSS
What is the current behaviour?
What is the expected behaviour?
Slow console response
How to reproduce the issue? Query bellow, takes 8+ seconds...