Re: Planning time is high in Postgres 11.5 Compared with Postgres 10.11

Hi Tom,

  You didn't answer the question:

>> First thing to do is to look into pg_stats and see how large those
>> arrays actually are in each case ...

We reproduced issue with sample tables "child" and "core", moreover these tables  doesn't contains any data in it in both postgresql 10 & 11.

select count(1) from child --0
select count(1) from core --0

I did analyzed both the tables using the below command and after which i ran the below explain analyze and took the perf report.

Vacuum analyze child;
vacuum analyze core;

Both configuration parameters are identical in V10 & V11. But we observe high planning time in V11 when compared with V10.

PostDB11=# explain analyze  SELECT --DISTINCT kc.childid AS rlid,
PostDB11-#     kc.id AS rlrightid--,
PostDB11-#    -- 0 AS rlproxytype
PostDB11-#    FROM child kc
PostDB11-#   WHERE NOT (EXISTS ( SELECT 1
PostDB11(#            FROM core
PostDB11(#           WHERE kc.id = core.groupid));


Postgres 10

-bash-4.2$ perf report -g
Samples: 6K of event 'cpu-clock:uhH', Event count (approx.): 1541000000
  Children      Self  Command   Shared Object          Symbol
+   13.72%     0.00%  postgres  [unknown]              [.] 0000000000000000
+    5.34%     0.08%  postgres  libc-2.17.so           [.] __vsnprintf_chk
+    4.62%     1.52%  postgres  libc-2.17.so           [.] vfprintf
+    4.59%     4.59%  postgres  postgres               [.] SearchCatCache
+    4.12%     0.00%  postgres  [unknown]              [.] 0x0000000001d86000
+    4.09%     4.09%  postgres  postgres               [.] base_yyparse
+    2.09%     0.00%  postgres  [unknown]              [.] 0x312e2e32362e3135
+    2.04%     2.03%  postgres  postgres               [.] hash_search_with_hash_value
     1.83%     1.83%  postgres  libc-2.17.so           [.] __strcmp_sse42
+    1.78%     0.00%  postgres  [unknown]              [.] 0x0000000001d83638
+    1.74%     0.00%  postgres  [unknown]              [.] 0x0000000000cb3260
+    1.49%     1.43%  postgres  libc-2.17.so           [.] __GI___printf_fp_l



Postgres 11


bash-4.2$ perf report -g
Samples: 235K of event 'cpu-clock:uhH', Event count (approx.): 58888750000
  Children      Self  Command   Shared Object       Symbol
+   37.73%    37.73%  postgres  postgres            [.] FunctionCall2Coll
+   28.57%    28.57%  postgres  postgres            [.] eqjoinsel
+   13.94%    13.94%  postgres  postgres            [.] int8eq
+    5.68%     5.68%  postgres  postgres            [.] eqjoinsel_semi.isra.3
+    1.78%     0.14%  postgres  libc-2.17.so        [.] __clock_gettime
+    1.76%     1.76%  postgres  postgres            [.] pglz_decompress
+    1.68%     1.68%  postgres  [vdso]              [.] __vdso_clock_gettime
+    1.43%     0.00%  postgres  [unknown]           [.] 0000000000000000
+    1.22%     0.00%  postgres  postgres            [.] TTSOpsVirtual+0x0
+    0.93%     0.00%  postgres  postgres            [.] TTSOpsBufferHeapTuple+0x0
+    0.72%     0.00%  postgres  [unknown]           [.] 0x00000000026bb0d0
     0.44%     0.44%  postgres  postgres            [.] deconstruct_array

Thanks,

Avinash