Thread
Commits
-
Suppress unnecessary RelabelType nodes in more cases.
- 30d5c6bf2e09 12.3 landed
- a477bfc1dfb8 13.0 landed
-
information_schema performance in Postgres 12
Eric Gillum <eric@hazel.co> — 2020-02-26T04:53:58Z
Hello, I've noticed a ~50x regression in execution time for a query when moving from Postgres 11.6 to 12.1. Here's an example: SELECT tc.table_name, kcu.column_name, ccu.table_name AS foreign_table_name, ccu.column_name AS foreign_column_name FROM information_schema.table_constraints tc JOIN information_schema.key_column_usage kcu ON tc.constraint_name = kcu.constraint_name JOIN information_schema.constraint_column_usage ccu ON ccu.constraint_name = tc.constraint_name WHERE tc.constraint_type = 'FOREIGN KEY' AND ccu.table_name = 'patient' ORDER BY tc.table_name, kcu.column_name, ccu.table_name, ccu.column_name; The only parameter to the query is the table name, in this case 'patient'. My schema has maybe 50 tables and no table has more than 50 columns. Most tables have around one to three foreign keys. I did as straightforward a pg_upgrade as I could, so I don't know what the difference there would be. Insight much appreciated. My thought is this is a large difference in execution time, and I'd like to know if I can get that time back. Anyway, I could move toward caching the results of these queries, so it's not the worst thing that could've happened. Overall 12.1 is looking like a godsend over 11.6 for many other use cases I have! PostgreSQL 11.6 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM version 8.1.0 (clang-802.0.42), 64-bit PostgreSQL 12.1 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM version 8.1.0 (clang-802.0.42), 64-bit Here's the ANALYZE output (from 11.6 then 12.1): Sort (cost=1370.57..1370.59 rows=8 width=128) (actual time=10.416..10.417 rows=9 loops=1) Sort Key: "*SELECT* 1".table_name, ((a.attname)::information_schema.sql_identifier), (("*SELECT* 1_1".attname)::information_schema.sql_identifier) Sort Method: quicksort Memory: 25kB -> Nested Loop (cost=418.80..1370.45 rows=8 width=128) (actual time=7.262..10.384 rows=9 loops=1) -> Hash Join (cost=418.52..1247.29 rows=370 width=200) (actual time=7.242..10.300 rows=9 loops=1) Hash Cond: (((c.conname)::information_schema.sql_identifier)::text = ("*SELECT* 1".constraint_name)::text) -> ProjectSet (cost=30.87..254.69 rows=37000 width=341) (actual time=0.612..5.179 rows=266 loops=1) -> Hash Join (cost=30.87..60.26 rows=37 width=95) (actual time=0.439..1.156 rows=256 loops=1) Hash Cond: (c.connamespace = nc.oid) -> Hash Join (cost=29.74..58.96 rows=37 width=99) (actual time=0.404..0.957 rows=256 loops=1) Hash Cond: (r.relnamespace = nr.oid) -> Hash Join (cost=28.61..57.59 rows=55 width=103) (actual time=0.379..0.779 rows=256 loops=1) Hash Cond: (c.conrelid = r.oid) -> Seq Scan on pg_constraint c (cost=0.00..28.32 rows=252 width=95) (actual time=0.011..0.174 rows=256 loops=1) Filter: (contype = ANY ('{p,u,f}'::"char"[])) Rows Removed by Filter: 63 -> Hash (cost=27.07..27.07 rows=123 width=12) (actual time=0.359..0.359 rows=124 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 14kB -> Seq Scan on pg_class r (cost=0.00..27.07 rows=123 width=12) (actual time=0.008..0.307 rows=124 loops=1) Filter: (relkind = ANY ('{r,p}'::"char"[])) Rows Removed by Filter: 447 -> Hash (cost=1.07..1.07 rows=4 width=4) (actual time=0.018..0.019 rows=5 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Seq Scan on pg_namespace nr (cost=0.00..1.07 rows=4 width=4) (actual time=0.006..0.013 rows=5 loops=1) Filter: (NOT pg_is_other_temp_schema(oid)) Rows Removed by Filter: 4 -> Hash (cost=1.06..1.06 rows=6 width=4) (actual time=0.027..0.027 rows=9 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Seq Scan on pg_namespace nc (cost=0.00..1.06 rows=6 width=4) (actual time=0.012..0.015 rows=9 loops=1) -> Hash (cost=387.62..387.62 rows=2 width=256) (actual time=4.938..4.938 rows=9 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 11kB -> Hash Join (cost=113.20..387.62 rows=2 width=256) (actual time=2.928..4.925 rows=9 loops=1) Hash Cond: (("*SELECT* 1".constraint_name)::text = (("*SELECT* 1_1".conname)::information_schema.sql_identifier)::text) -> Append (cost=0.41..273.87 rows=150 width=64) (actual time=0.069..2.819 rows=178 loops=1) -> Subquery Scan on "*SELECT* 1" (cost=0.41..50.91 rows=1 width=64) (actual time=0.068..2.761 rows=178 loops=1) -> Nested Loop (cost=0.41..50.90 rows=1 width=320) (actual time=0.067..2.694 rows=178 loops=1) -> Nested Loop (cost=0.28..50.60 rows=1 width=132) (actual time=0.056..2.060 rows=178 loops=1) Join Filter: (c_1.connamespace = nc_1.oid) Rows Removed by Join Filter: 1424 -> Nested Loop (cost=0.28..49.47 rows=1 width=136) (actual time=0.046..1.036 rows=178 loops=1) -> Seq Scan on pg_constraint c_1 (cost=0.00..32.64 rows=2 width=72) (actual time=0.030..0.189 rows=178 loops=1) Filter: ((contype <> ALL ('{t,x}'::"char"[])) AND (((CASE contype WHEN 'c'::"char" THEN 'CHECK'::text WHEN 'f'::"char" THEN 'FOREIGN KEY'::text WHEN 'p'::"char" THEN 'PRIMARY KEY'::text WHEN 'u'::"char" THEN 'UNIQUE'::text ELSE NULL::text END)::information_schema.character_data)::text = 'FOREIGN KEY'::text)) Rows Removed by Filter: 141 -> Index Scan using pg_class_oid_index on pg_class r_1 (cost=0.28..8.33 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=178) Index Cond: (oid = c_1.conrelid) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND (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))) -> Seq Scan on pg_namespace nc_1 (cost=0.00..1.06 rows=6 width=4) (actual time=0.001..0.003 rows=9 loops=178) -> Index Only Scan using pg_namespace_oid_index on pg_namespace nr_1 (cost=0.13..0.24 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=178) Index Cond: (oid = r_1.relnamespace) Filter: (NOT pg_is_other_temp_schema(oid)) Heap Fetches: 178 -> Subquery Scan on "*SELECT* 2" (cost=46.27..222.20 rows=149 width=64) (actual time=0.001..0.002 rows=0 loops=1) -> Result (cost=46.27..220.71 rows=149 width=320) (actual time=0.001..0.001 rows=0 loops=1) One-Time Filter: ((('CHECK'::character varying)::information_schema.character_data)::text = 'FOREIGN KEY'::text) -> Hash Join (cost=46.27..215.50 rows=149 width=74) (never executed) Hash Cond: (r_2.relnamespace = nr_2.oid) -> Hash Join (cost=45.14..213.37 rows=223 width=74) (never executed) Hash Cond: (a_1.attrelid = r_2.oid) -> Seq Scan on pg_attribute a_1 (cost=0.00..164.39 rows=1451 width=6) (never executed) Filter: (attnotnull AND (NOT attisdropped) AND (attnum > 0)) -> Hash (cost=44.06..44.06 rows=87 width=72) (never executed) -> Seq Scan on pg_class r_2 (cost=0.00..44.06 rows=87 width=72) (never executed) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND (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=1.07..1.07 rows=4 width=4) (never executed) -> Seq Scan on pg_namespace nr_2 (cost=0.00..1.07 rows=4 width=4) (never executed) Filter: (NOT pg_is_other_temp_schema(oid)) -> Hash (cost=112.77..112.77 rows=2 width=192) (actual time=2.009..2.010 rows=18 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 12kB -> Append (cost=46.90..112.77 rows=2 width=192) (actual time=0.802..1.983 rows=18 loops=1) -> Subquery Scan on "*SELECT* 1_1" (cost=46.90..46.93 rows=1 width=192) (actual time=0.802..0.815 rows=6 loops=1) -> Unique (cost=46.90..46.92 rows=1 width=324) (actual time=0.800..0.811 rows=6 loops=1) -> Sort (cost=46.90..46.91 rows=1 width=324) (actual time=0.799..0.801 rows=12 loops=1) Sort Key: nr_3.nspname, r_3.relname, r_3.relowner, a_2.attname, nc_2.nspname, c_2.conname Sort Method: quicksort Memory: 31kB -> Nested Loop (cost=0.97..46.89 rows=1 width=324) (actual time=0.454..0.775 rows=12 loops=1) -> Nested Loop (cost=0.84..46.49 rows=1 width=264) (actual time=0.442..0.729 rows=12 loops=1) -> Nested Loop (cost=0.57..45.44 rows=1 width=200) (actual time=0.308..0.584 rows=30 loops=1) Join Filter: (r_3.oid = a_2.attrelid) -> Nested Loop (cost=0.29..42.19 rows=1 width=148) (actual time=0.291..0.406 rows=30 loops=1) -> Nested Loop (cost=0.00..33.87 rows=1 width=136) (actual time=0.263..0.328 rows=1 loops=1) Join Filter: (nr_3.oid = r_3.relnamespace) Rows Removed by Join Filter: 8 -> Seq Scan on pg_class r_3 (cost=0.00..32.73 rows=1 width=76) (actual time=0.250..0.315 rows=1 loops=1) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND pg_has_role(relowner, 'USAGE'::text) AND (((relname)::information_schema.sql_identifier)::text = 'patient'::text)) Rows Removed by Filter: 570 -> Seq Scan on pg_namespace nr_3 (cost=0.00..1.06 rows=6 width=68) (actual time=0.007..0.009 rows=9 loops=1) -> Index Scan using pg_depend_reference_index on pg_depend d (cost=0.29..8.31 rows=1 width=12) (actual time=0.025..0.061 rows=30 loops=1) Index Cond: ((refclassid = '1259'::oid) AND (refobjid = r_3.oid)) Filter: (classid = '2606'::oid) Rows Removed by Filter: 15 -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a_2 (cost=0.28..3.24 rows=1 width=70) (actual time=0.005..0.005 rows=1 loops=30) Index Cond: ((attrelid = d.refobjid) AND (attnum = d.refobjsubid)) Filter: (NOT attisdropped) -> Index Scan using pg_constraint_oid_index on pg_constraint c_2 (cost=0.27..1.03 rows=1 width=72) (actual time=0.004..0.004 rows=0 loops=30) Index Cond: (oid = d.objid) Filter: (contype = 'c'::"char") Rows Removed by Filter: 1 -> Index Scan using pg_namespace_oid_index on pg_namespace nc_2 (cost=0.13..0.34 rows=1 width=68) (actual time=0.003..0.003 rows=1 loops=12) Index Cond: (oid = c_2.connamespace) -> Subquery Scan on "*SELECT* 2_1" (cost=33.16..65.83 rows=1 width=192) (actual time=0.454..1.162 rows=12 loops=1) -> Nested Loop (cost=33.16..65.82 rows=1 width=324) (actual time=0.453..1.155 rows=12 loops=1) -> Nested Loop (cost=33.03..65.62 rows=1 width=196) (actual time=0.441..1.111 rows=12 loops=1) Join Filter: (r_4.oid = a_3.attrelid) -> Nested Loop (cost=32.75..62.89 rows=1 width=191) (actual time=0.417..0.654 rows=12 loops=1) Join Filter: (r_4.relnamespace = nr_4.oid) Rows Removed by Join Filter: 96 -> Hash Join (cost=32.75..61.76 rows=1 width=195) (actual time=0.407..0.578 rows=12 loops=1) Hash Cond: (CASE c_3.contype WHEN 'f'::"char" THEN c_3.confrelid ELSE c_3.conrelid END = r_4.oid) -> Seq Scan on pg_constraint c_3 (cost=0.00..28.32 rows=252 width=123) (actual time=0.008..0.147 rows=256 loops=1) Filter: (contype = ANY ('{p,u,f}'::"char"[])) Rows Removed by Filter: 63 -> Hash (cost=32.73..32.73 rows=1 width=72) (actual time=0.308..0.308 rows=1 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Seq Scan on pg_class r_4 (cost=0.00..32.73 rows=1 width=72) (actual time=0.242..0.303 rows=1 loops=1) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND pg_has_role(relowner, 'USAGE'::text) AND (((relname)::information_schema.sql_identifier)::text = 'patient'::text)) Rows Removed by Filter: 570 -> Seq Scan on pg_namespace nr_4 (cost=0.00..1.06 rows=6 width=4) (actual time=0.001..0.003 rows=9 loops=12) -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a_3 (cost=0.29..2.72 rows=1 width=70) (actual time=0.012..0.036 rows=1 loops=12) Index Cond: (attrelid = CASE c_3.contype WHEN 'f'::"char" THEN c_3.confrelid ELSE c_3.conrelid END) Filter: ((NOT attisdropped) AND (attnum = ANY (CASE c_3.contype WHEN 'f'::"char" THEN c_3.confkey ELSE c_3.conkey END))) Rows Removed by Filter: 33 -> Index Only Scan using pg_namespace_oid_index on pg_namespace nc_3 (cost=0.13..0.18 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=12) Index Cond: (oid = c_3.connamespace) Heap Fetches: 12 -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a (cost=0.28..0.32 rows=1 width=70) (actual time=0.007..0.007 rows=1 loops=9) Index Cond: ((attrelid = r.oid) AND (attnum = ((information_schema._pg_expandarray(c.conkey))).x)) Filter: ((NOT attisdropped) AND (pg_has_role(r.relowner, 'USAGE'::text) OR has_column_privilege(r.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text))) Planning Time: 6.653 ms Execution Time: 10.890 ms (129 rows) Sort (cost=845.27..845.27 rows=1 width=256) (actual time=538.828..538.829 rows=9 loops=1) Sort Key: "*SELECT* 1".table_name, ((a.attname)::information_schema.sql_identifier), (("*SELECT* 1_1".relname)::information_schema.sql_identifier), (("*SELECT* 1_1".attname)::information_schema.sql_identifier) Sort Method: quicksort Memory: 29kB -> Nested Loop (cost=84.65..845.26 rows=1 width=256) (actual time=143.802..538.780 rows=9 loops=1) -> Nested Loop (cost=84.37..844.93 rows=1 width=232) (actual time=143.780..538.653 rows=9 loops=1) Join Filter: ((c_1.conname)::name = ("*SELECT* 1".constraint_name)::name) Rows Removed by Join Filter: 2127 -> Subquery Scan on "*SELECT* 1" (cost=0.41..39.31 rows=1 width=128) (actual time=0.165..2.650 rows=178 loops=1) -> Nested Loop (cost=0.41..39.30 rows=1 width=512) (actual time=0.162..2.587 rows=178 loops=1) -> Nested Loop (cost=0.28..38.96 rows=1 width=132) (actual time=0.133..1.973 rows=178 loops=1) Join Filter: (c.connamespace = nc.oid) Rows Removed by Join Filter: 1068 -> Nested Loop (cost=0.28..37.81 rows=1 width=136) (actual time=0.125..1.159 rows=178 loops=1) -> Seq Scan on pg_constraint c (cost=0.00..20.98 rows=2 width=72) (actual time=0.102..0.231 rows=178 loops=1) Filter: ((contype <> ALL ('{t,x}'::"char"[])) AND ((CASE contype WHEN 'c'::"char" THEN 'CHECK'::text WHEN 'f'::"char" THEN 'FOREIGN KEY'::text WHEN 'p'::"char" THEN 'PRIMARY KEY'::text WHEN 'u'::"char" THEN 'UNIQUE'::text ELSE NULL::text END)::text = 'FOREIGN KEY'::text)) Rows Removed by Filter: 141 -> Index Scan using pg_class_oid_index on pg_class r (cost=0.28..8.33 rows=1 width=72) (actual time=0.004..0.004 rows=1 loops=178) Index Cond: (oid = c.conrelid) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND (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))) -> Seq Scan on pg_namespace nc (cost=0.00..1.07 rows=7 width=4) (actual time=0.001..0.001 rows=7 loops=178) -> Index Only Scan using pg_namespace_oid_index on pg_namespace nr (cost=0.13..0.29 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=178) Index Cond: (oid = r.relnamespace) Filter: (NOT pg_is_other_temp_schema(oid)) Heap Fetches: 178 -> Hash Join (cost=83.96..805.59 rows=2 width=296) (actual time=0.448..3.007 rows=12 loops=178) Hash Cond: ((c_1.conname)::name = ("*SELECT* 1_1".conname)::name) -> ProjectSet (cost=32.67..245.53 rows=37000 width=341) (actual time=0.023..2.910 rows=266 loops=178) -> Hash Join (cost=32.67..51.09 rows=37 width=95) (actual time=0.010..0.494 rows=256 loops=178) Hash Cond: (c_1.connamespace = nc_1.oid) -> Hash Join (cost=31.51..49.78 rows=37 width=99) (actual time=0.010..0.391 rows=256 loops=178) Hash Cond: (r_1.relnamespace = nr_1.oid) -> Hash Join (cost=30.36..48.42 rows=51 width=103) (actual time=0.009..0.287 rows=256 loops=178) Hash Cond: (c_1.conrelid = r_1.oid) -> Seq Scan on pg_constraint c_1 (cost=0.00..17.39 rows=256 width=95) (actual time=0.006..0.124 rows=256 loops=178) Filter: (contype = ANY ('{p,u,f}'::"char"[])) Rows Removed by Filter: 63 -> Hash (cost=28.80..28.80 rows=125 width=12) (actual time=0.386..0.386 rows=125 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 14kB -> Seq Scan on pg_class r_1 (cost=0.00..28.80 rows=125 width=12) (actual time=0.006..0.336 rows=125 loops=1) Filter: (relkind = ANY ('{r,p}'::"char"[])) Rows Removed by Filter: 499 -> Hash (cost=1.09..1.09 rows=5 width=4) (actual time=0.043..0.043 rows=5 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Seq Scan on pg_namespace nr_1 (cost=0.00..1.09 rows=5 width=4) (actual time=0.011..0.038 rows=5 loops=1) Filter: (NOT pg_is_other_temp_schema(oid)) Rows Removed by Filter: 2 -> Hash (cost=1.07..1.07 rows=7 width=4) (actual time=0.018..0.018 rows=7 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Seq Scan on pg_namespace nc_1 (cost=0.00..1.07 rows=7 width=4) (actual time=0.005..0.007 rows=7 loops=1) -> Hash (cost=51.27..51.27 rows=2 width=192) (actual time=1.312..1.312 rows=18 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 12kB -> Append (cost=21.33..51.27 rows=2 width=192) (actual time=0.508..1.291 rows=18 loops=1) -> Subquery Scan on "*SELECT* 1_1" (cost=21.33..21.36 rows=1 width=192) (actual time=0.508..0.520 rows=6 loops=1) -> Unique (cost=21.33..21.35 rows=1 width=324) (actual time=0.506..0.516 rows=6 loops=1) -> Sort (cost=21.33..21.33 rows=1 width=324) (actual time=0.505..0.507 rows=12 loops=1) Sort Key: nr_2.nspname, r_2.relname, r_2.relowner, a_1.attname, nc_2.nspname, c_2.conname Sort Method: quicksort Memory: 31kB -> Nested Loop (cost=1.12..21.32 rows=1 width=324) (actual time=0.110..0.455 rows=12 loops=1) -> Nested Loop (cost=0.99..20.93 rows=1 width=264) (actual time=0.102..0.416 rows=12 loops=1) -> Nested Loop (cost=0.84..20.41 rows=1 width=200) (actual time=0.096..0.305 rows=30 loops=1) Join Filter: (r_2.oid = a_1.attrelid) -> Nested Loop (cost=0.56..17.77 rows=1 width=148) (actual time=0.057..0.117 rows=30 loops=1) -> Nested Loop (cost=0.28..9.46 rows=1 width=136) (actual time=0.020..0.021 rows=1 loops=1) Join Filter: (nr_2.oid = r_2.relnamespace) Rows Removed by Join Filter: 6 -> Index Scan using pg_class_relname_nsp_index on pg_class r_2 (cost=0.28..8.30 rows=1 width=76) (actual time=0.010..0.011 rows=1 loops=1) Index Cond: ((relname)::name = 'patient'::name) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND pg_has_role(relowner, 'USAGE'::text)) -> Seq Scan on pg_namespace nr_2 (cost=0.00..1.07 rows=7 width=68) (actual time=0.005..0.006 rows=7 loops=1) -> Index Scan using pg_depend_reference_index on pg_depend d (cost=0.29..8.31 rows=1 width=12) (actual time=0.034..0.081 rows=30 loops=1) Index Cond: ((refclassid = '1259'::oid) AND (refobjid = r_2.oid)) Filter: (classid = '2606'::oid) Rows Removed by Filter: 15 -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a_1 (cost=0.28..2.62 rows=1 width=70) (actual time=0.005..0.005 rows=1 loops=30) Index Cond: ((attrelid = d.refobjid) AND (attnum = d.refobjsubid)) Filter: (NOT attisdropped) -> Index Scan using pg_constraint_oid_index on pg_constraint c_2 (cost=0.15..0.51 rows=1 width=72) (actual time=0.003..0.003 rows=0 loops=30) Index Cond: (oid = d.objid) Filter: (contype = 'c'::"char") Rows Removed by Filter: 1 -> Index Scan using pg_namespace_oid_index on pg_namespace nc_2 (cost=0.13..0.34 rows=1 width=68) (actual time=0.002..0.002 rows=1 loops=12) Index Cond: (oid = c_2.connamespace) -> Subquery Scan on "*SELECT* 2" (cost=8.73..29.90 rows=1 width=192) (actual time=0.137..0.766 rows=12 loops=1) -> Nested Loop (cost=8.73..29.89 rows=1 width=324) (actual time=0.137..0.761 rows=12 loops=1) -> Nested Loop (cost=8.60..29.68 rows=1 width=196) (actual time=0.125..0.717 rows=12 loops=1) Join Filter: (r_3.oid = a_2.attrelid) -> Nested Loop (cost=8.31..27.56 rows=1 width=191) (actual time=0.092..0.317 rows=12 loops=1) Join Filter: (r_3.relnamespace = nr_3.oid) Rows Removed by Join Filter: 72 -> Hash Join (cost=8.31..26.40 rows=1 width=195) (actual time=0.085..0.255 rows=12 loops=1) Hash Cond: (CASE c_3.contype WHEN 'f'::"char" THEN c_3.confrelid ELSE c_3.conrelid END = r_3.oid) -> Seq Scan on pg_constraint c_3 (cost=0.00..17.39 rows=256 width=123) (actual time=0.013..0.130 rows=256 loops=1) Filter: (contype = ANY ('{p,u,f}'::"char"[])) Rows Removed by Filter: 63 -> Hash (cost=8.30..8.30 rows=1 width=72) (actual time=0.015..0.015 rows=1 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 9kB -> Index Scan using pg_class_relname_nsp_index on pg_class r_3 (cost=0.28..8.30 rows=1 width=72) (actual time=0.011..0.012 rows=1 loops=1) Index Cond: ((relname)::name = 'patient'::name) Filter: ((relkind = ANY ('{r,p}'::"char"[])) AND pg_has_role(relowner, 'USAGE'::text)) -> Seq Scan on pg_namespace nr_3 (cost=0.00..1.07 rows=7 width=4) (actual time=0.001..0.002 rows=7 loops=12) -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a_2 (cost=0.29..2.11 rows=1 width=70) (actual time=0.012..0.032 rows=1 loops=12) Index Cond: (attrelid = CASE c_3.contype WHEN 'f'::"char" THEN c_3.confrelid ELSE c_3.conrelid END) Filter: ((NOT attisdropped) AND (attnum = ANY (CASE c_3.contype WHEN 'f'::"char" THEN c_3.confkey ELSE c_3.conkey END))) Rows Removed by Filter: 33 -> Index Only Scan using pg_namespace_oid_index on pg_namespace nc_3 (cost=0.13..0.20 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=12) Index Cond: (oid = c_3.connamespace) Heap Fetches: 12 -> Index Scan using pg_attribute_relid_attnum_index on pg_attribute a (cost=0.28..0.32 rows=1 width=70) (actual time=0.011..0.011 rows=1 loops=9) Index Cond: ((attrelid = r_1.oid) AND (attnum = ((information_schema._pg_expandarray(c_1.conkey))).x)) Filter: ((NOT attisdropped) AND (pg_has_role(r_1.relowner, 'USAGE'::text) OR has_column_privilege(r_1.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text))) Planning Time: 10.207 ms Execution Time: 539.506 ms (112 rows) -
Re: information_schema performance in Postgres 12
Adrian Klaver <adrian.klaver@aklaver.com> — 2020-02-26T15:56:19Z
On 2/25/20 8:53 PM, Eric Gillum wrote: > Hello, > > I've noticed a ~50x regression in execution time for a query when moving > from Postgres 11.6 to 12.1. Here's an example: > > SELECT tc.table_name, kcu.column_name, ccu.table_name AS > foreign_table_name, ccu.column_name AS foreign_column_name FROM > information_schema.table_constraints tc JOIN > information_schema.key_column_usage kcu ON tc.constraint_name = > kcu.constraint_name JOIN information_schema.constraint_column_usage ccu > ON ccu.constraint_name = tc.constraint_name WHERE tc.constraint_type = > 'FOREIGN KEY' AND ccu.table_name = 'patient' ORDER BY tc.table_name, > kcu.column_name, ccu.table_name, ccu.column_name; > > The only parameter to the query is the table name, in this case > 'patient'. My schema has maybe 50 tables and no table has more than 50 > columns. Most tables have around one to three foreign keys. > > I did as straightforward a pg_upgrade as I could, so I don't know what > the difference there would be. Did you do?: https://www.postgresql.org/docs/12/pgupgrade.html 14. Statistics Because optimizer statistics are not transferred by pg_upgrade, you will be instructed to run a command to regenerate that information at the end of the upgrade. You might need to set connection parameters to match your new cluster. > > Insight much appreciated. My thought is this is a large difference in > execution time, and I'd like to know if I can get that time back. > Anyway, I could move toward caching the results of these queries, so > it's not the worst thing that could've happened. Overall 12.1 is looking > like a godsend over 11.6 for many other use cases I have! > > PostgreSQL 11.6 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM > version 8.1.0 (clang-802.0.42), 64-bit > PostgreSQL 12.1 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM > version 8.1.0 (clang-802.0.42), 64-bit > -- Adrian Klaver adrian.klaver@aklaver.com
-
Re: information_schema performance in Postgres 12
Eric Gillum <eric@hazel.co> — 2020-02-26T16:20:36Z
I had not run the script per se, I had run ANALYZE. I just re-upgraded to a separate cluster and ran the provided script. The query still takes about 500ms. On Wed, Feb 26, 2020 at 7:56 AM Adrian Klaver <adrian.klaver@aklaver.com> wrote: > On 2/25/20 8:53 PM, Eric Gillum wrote: > > Hello, > > > > I've noticed a ~50x regression in execution time for a query when moving > > from Postgres 11.6 to 12.1. Here's an example: > > > > SELECT tc.table_name, kcu.column_name, ccu.table_name AS > > foreign_table_name, ccu.column_name AS foreign_column_name FROM > > information_schema.table_constraints tc JOIN > > information_schema.key_column_usage kcu ON tc.constraint_name = > > kcu.constraint_name JOIN information_schema.constraint_column_usage ccu > > ON ccu.constraint_name = tc.constraint_name WHERE tc.constraint_type = > > 'FOREIGN KEY' AND ccu.table_name = 'patient' ORDER BY tc.table_name, > > kcu.column_name, ccu.table_name, ccu.column_name; > > > > The only parameter to the query is the table name, in this case > > 'patient'. My schema has maybe 50 tables and no table has more than 50 > > columns. Most tables have around one to three foreign keys. > > > > I did as straightforward a pg_upgrade as I could, so I don't know what > > the difference there would be. > > Did you do?: > https://www.postgresql.org/docs/12/pgupgrade.html > > 14. Statistics > > Because optimizer statistics are not transferred by pg_upgrade, you will > be instructed to run a command to regenerate that information at the end > of the upgrade. You might need to set connection parameters to match > your new cluster. > > > > > Insight much appreciated. My thought is this is a large difference in > > execution time, and I'd like to know if I can get that time back. > > Anyway, I could move toward caching the results of these queries, so > > it's not the worst thing that could've happened. Overall 12.1 is looking > > like a godsend over 11.6 for many other use cases I have! > > > > PostgreSQL 11.6 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM > > version 8.1.0 (clang-802.0.42), 64-bit > > PostgreSQL 12.1 on x86_64-apple-darwin16.7.0, compiled by Apple LLVM > > version 8.1.0 (clang-802.0.42), 64-bit > > > > -- > Adrian Klaver > adrian.klaver@aklaver.com >
-
Re: information_schema performance in Postgres 12
Michael Lewis <mlewis@entrata.com> — 2020-02-26T16:40:42Z
Have you tried with JIT turned off in PG12? The long running node is ProjectSet type which is related to set returning functions. If that is getting evaluated differently in PG12, that may be issue.
-
Re: information_schema performance in Postgres 12
Eric Gillum <eric@hazel.co> — 2020-02-26T18:05:21Z
Does not seem to improve if I turn off JIT. # show jit; on # explain analyze SELECT tc.table_name, ... Planning Time: 8.806 ms Execution Time: 511.249 ms # set jit=false; # show jit; off # explain analyze SELECT tc.table_name, ... Planning Time: 8.980 ms Execution Time: 506.016 ms On Wed, Feb 26, 2020 at 8:41 AM Michael Lewis <mlewis@entrata.com> wrote: > Have you tried with JIT turned off in PG12? The long running node > is ProjectSet type which is related to set returning functions. If that is > getting evaluated differently in PG12, that may be issue. >
-
Re: information_schema performance in Postgres 12
Tom Lane <tgl@sss.pgh.pa.us> — 2020-02-26T23:35:06Z
Eric Gillum <eric@hazel.co> writes: > Does not seem to improve if I turn off JIT. AFAICT you're just getting sideswiped by the poor quality of our estimates for messy sub-SELECTs :-(. v12 is estimating that it will get only one row out of the information_schema.table_constraints sub-select, which causes it to decide that it'd be a cool idea to put that on the outside of a nestloop with a moderately-expensive other arm. But actually it gets 178 rows out, so the other arm gets iterated 178 times, and you lose. -> Nested Loop (cost=84.37..844.93 rows=1 width=232) (actual time=143.780..538.653 rows=9 loops=1) Join Filter: ((c_1.conname)::name = ("*SELECT* 1".constraint_name)::name) Rows Removed by Join Filter: 2127 -> Subquery Scan on "*SELECT* 1" (cost=0.41..39.31 rows=1 width=128) (actual time=0.165..2.650 rows=178 loops=1) ... -> Hash Join (cost=83.96..805.59 rows=2 width=296) (actual time=0.448..3.007 rows=12 loops=178) Now, v11 had the same poor estimate, but it happens not to make that particular disastrous choice, in this particular case. I think you just got lucky on that before, though, and now are not lucky. We did make some changes in v12 around the handling of conditions involving information_schema.sql_identifier casts, which the info-schema views are full of, so the idea that some other estimates might've changed is not very surprising. For the most part those changes should've led to improved estimates, but in this case the big problem is this unrelated bad estimate. The crux of the misestimate seems to be here: -> Seq Scan on pg_constraint c (cost=0.00..20.98 rows=2 width=72) (actual time=0.102..0.231 rows=178 loops=1) Filter: ((contype <> ALL ('{t,x}'::"char"[])) AND ((CASE contype WHEN 'c'::"char" THEN 'CHECK'::text WHEN 'f'::"char" THEN 'FOREIGN KEY'::text WHEN 'p'::"char" THEN 'PRIMARY KEY'::text WHEN 'u'::"char" THEN 'UNIQUE'::text ELSE NULL::text END)::text = 'FOREIGN KEY'::text)) The "contype <> ALL ..." condition is actually estimated pretty well, AFAICT, but the condition on a CASE clause is not something that the planner has any understanding of, so it falls back to a default estimate that is pretty far off for this case. I noticed along the way that you show v12 as doing an unnecessary sort that v11 was smart enough to avoid: Sort (cost=1370.57..1370.59 rows=8 width=128) (actual time=10.416..10.417 rows=9 loops=1) Sort Key: "*SELECT* 1".table_name, ((a.attname)::information_schema.sql_identifier), (("*SELECT* 1_1".attname)::information_schema.sql_identifier) Sort (cost=845.27..845.27 rows=1 width=256) (actual time=538.828..538.829 rows=9 loops=1) Sort Key: "*SELECT* 1".table_name, ((a.attname)::information_schema.sql_identifier), (("*SELECT* 1_1".relname)::information_schema.sql_identifier), (("*SELECT* 1_1".attname)::information_schema.sql_identifier) It's not actually necessary to sort on the relname (third sort key) because your WHERE clause constrains that to be a constant. v11 saw that but v12 fails to, which is a bug that I just pushed a fix for. It's not terribly important for your example, but it might matter more in other cases. As far as solving your larger problem goes, I don't have any near-term ideas other than to rewrite the query to look directly at the system catalogs rather than going through information_schema views. But that's not a very nice answer. regards, tom lane