Re: Creating foreign key on partitioned table is too slow

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