On Fri, Oct 25, 2019 at 12:17:58AM +0200, Tomas Vondra wrote:
...
FWIW, even with this fix it still takes an awful lot to create the
foreign key, because the CPU is stuck doing this
60.78% 60.78% postgres postgres [.] bms_equal
32.58% 32.58% postgres postgres [.] get_eclass_for_sort_expr
3.83% 3.83% postgres postgres [.] add_child_rel_equivalences
0.23% 0.00% postgres [unknown] [.] 0x0000000000000005
0.22% 0.00% postgres [unknown] [.] 0000000000000000
0.18% 0.18% postgres postgres [.] AllocSetCheck
...
Haven't looked into the details yet.
OK, a bit more info. A better perf report (with framepointers etc) looks
like this:
+ 99.98% 0.00% postgres [unknown] [.] 0x495641002c4d133d
+ 99.98% 0.00% postgres libc-2.29.so [.] __libc_start_main
+ 99.98% 0.00% postgres postgres [.] startup_hacks
+ 99.98% 0.00% postgres postgres [.] PostmasterMain
+ 99.98% 0.00% postgres postgres [.] ServerLoop
+ 99.98% 0.00% postgres postgres [.] BackendStartup
+ 99.98% 0.00% postgres postgres [.] ExitPostmaster
+ 99.98% 0.00% postgres postgres [.] PostgresMain
+ 99.98% 0.00% postgres postgres [.] exec_simple_query
+ 99.98% 0.00% postgres postgres [.] PortalRun
+ 99.98% 0.00% postgres postgres [.] PortalRunMulti
+ 99.98% 0.00% postgres postgres [.] PortalRunUtility
+ 99.98% 0.00% postgres postgres [.] ProcessUtility
+ 99.98% 0.00% postgres postgres [.] standard_ProcessUtility
+ 99.98% 0.00% postgres postgres [.] ProcessUtilitySlow
+ 99.98% 0.00% postgres postgres [.] AlterTable
+ 99.98% 0.00% postgres postgres [.] ATController
+ 99.98% 0.00% postgres postgres [.] ATRewriteTables
+ 99.98% 0.00% postgres postgres [.] validateForeignKeyConstraint
+ 99.98% 0.00% postgres postgres [.] RI_Initial_Check
+ 99.96% 0.00% postgres postgres [.] SPI_execute_snapshot
+ 99.86% 0.00% postgres postgres [.] _SPI_execute_plan
+ 99.70% 0.00% postgres postgres [.] GetCachedPlan
+ 99.70% 0.00% postgres postgres [.] BuildCachedPlan
+ 99.66% 0.00% postgres postgres [.] pg_plan_queries
+ 99.66% 0.00% postgres postgres [.] pg_plan_query
+ 99.66% 0.00% postgres postgres [.] planner
+ 99.66% 0.00% postgres postgres [.] standard_planner
+ 99.62% 0.00% postgres postgres [.] subquery_planner
+ 99.62% 0.00% postgres postgres [.] grouping_planner
+ 99.62% 0.00% postgres postgres [.] query_planner
+ 99.31% 0.00% postgres postgres [.] make_one_rel
+ 97.53% 0.00% postgres postgres [.] set_base_rel_pathlists
+ 97.53% 0.00% postgres postgres [.] set_rel_pathlist
+ 97.53% 0.01% postgres postgres [.] set_append_rel_pathlist
+ 97.42% 0.00% postgres postgres [.] set_plain_rel_pathlist
+ 97.40% 0.02% postgres postgres [.] create_index_paths
+ 97.16% 0.01% postgres postgres [.] get_index_paths
+ 97.12% 0.02% postgres postgres [.] build_index_paths
+ 96.67% 0.01% postgres postgres [.] build_index_pathkeys
+ 96.61% 0.01% postgres postgres [.] make_pathkey_from_sortinfo
+ 95.70% 21.27% postgres postgres [.] get_eclass_for_sort_expr
+ 75.21% 75.21% postgres postgres [.] bms_equal
+ 48.72% 0.00% postgres postgres [.] consider_index_join_clauses
+ 48.72% 0.00% postgres postgres [.]
consider_index_join_outer_rels
+ 48.72% 0.02% postgres postgres [.] get_join_index_paths
+ 1.78% 0.00% postgres postgres [.] set_base_rel_sizes
+ 1.78% 0.00% postgres postgres [.] set_rel_size
+ 1.78% 0.01% postgres postgres [.] set_append_rel_size
+ 1.66% 1.34% postgres postgres [.] add_child_rel_equivalences
It is (pretty much) a single callstack, i.e. each function is simply
calling the one below it (with some minor exceptions at the end, but
that's pretty negligible here).
This essentially says that planning queries executed by RI_Initial_Check
with many partitions is damn expensive. An example query is this one:
test=# \timing
test=# SELECT fk."aid" FROM ONLY "public"."history_60" fk LEFT OUTER
JOIN "public"."accounts" pk ON ( pk."aid" OPERATOR(pg_catalog.=)
fk."aid") WHERE pk."aid" IS NULL AND (fk."aid" IS NOT NULL);
aid
-----
(0 rows)
Time: 28791.492 ms (00:28.791)
Bear in mind those are *empty* tables, so the execution is pretty cheap
(explain analyze says the execution takes ~65ms, but the planning itself
takes ~28 seconds). And we have 8192 such partitions, which means we'd
spend ~230k seconds just planning the RI queries. That's 64 hours.
regards
--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
