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

Thanks Heikki,

I did reproduce on postgres 11.5 and took the perf report.

CS-PostDB11=# explain analyze  SELECT --DISTINCT kc.childid AS rlid,
CS-PostDB11-#     kc.id AS rlrightid--,
CS-PostDB11-#    -- 0 AS rlproxytype
CS-PostDB11-#    FROM child kc
CS-PostDB11-#   WHERE NOT (EXISTS ( SELECT 1
CS-PostDB11(#            FROM core
CS-PostDB11(#           WHERE kc.id = core.groupid));
                                                 QUERY PLAN
------------------------------------------------------------------------------------------------------------
 Hash Anti Join  (cost=51.62..102.61 rows=1736 width=8) (actual
time=0.005..0.007 rows=0 loops=1)
   Hash Cond: (kc.id = core.groupid)
   ->  Seq Scan on child kc  (cost=0.00..28.50 rows=1850 width=8) (actual
time=0.005..0.005 rows=0 loops=1)
   ->  Hash  (cost=28.50..28.50 rows=1850 width=8) (never executed)
         ->  Seq Scan on core  (cost=0.00..28.50 rows=1850 width=8) (never
executed)
 Planning Time: 11.378 ms
 Execution Time: 0.057 ms
(7 rows)

CS-PostDB11=# \timing
Timing is on.
CS-PostDB11=#
CS-PostDB11=# do $$
CS-PostDB11$# begin
CS-PostDB11$#    for i in 1..1000 loop
CS-PostDB11$#    execute $query$
CS-PostDB11$#      EXPLAIN SELECT kc.id AS rlrightid FROM child kc
CS-PostDB11$#      WHERE NOT (EXISTS ( SELECT 1 FROM core
CS-PostDB11$#                 WHERE kc.id = core.groupid));
CS-PostDB11$#    $query$;
CS-PostDB11$#    end loop;
CS-PostDB11$# end;
CS-PostDB11$# $$;


DO
Time: 10469.144 ms (00:10.469)

Perf Report Output:

Samples: 41K of event 'cpu-clock:uhH', Event count (approx.): 10461000000
  Children      Self  Command   Shared Object          Symbol



*+   49.97%    49.97%  postgres  postgres               [.]
FunctionCall2Coll+   17.58%    17.58%  postgres  postgres               [.]
int8eq+   15.15%    15.15%  postgres  postgres               [.] eqjoinsel+
  12.82%    12.82%  postgres  postgres               [.]
eqjoinsel_semi.isra.17*
+    1.82%     1.82%  postgres  postgres               [.] pglz_decompress
+    0.96%     0.00%  postgres  [unknown]              [.] 0000000000000000
+    0.62%     0.00%  postgres  [unknown]              [.]
0x0000000000000010
     0.56%     0.56%  postgres  postgres               [.] deconstruct_array
     0.20%     0.00%  postgres  [unknown]              [.]
0x0000000001674bd0

Thanks,
Avinash


On Mon, Dec 16, 2019 at 5:53 PM Heikki Linnakangas <[email protected]> wrote:

> On 16/12/2019 10:58, avinash varma wrote:
> > We have performed load test on 11.5 and observed high cpu utilization in
> > db server when compared with 10.11. On further investigation we observed
> > that below query is taking high planning time(highlighted in yellow) in
> > 11.5 and higher versions.
>
> I cannot reproduce that on my laptop. Planning takes less than 1 ms, and
> there is no big difference between server versions. Do you have any
> non-default settings in postgresql.conf?
>
> I think you'll need to do more investigation on your end, to figure out
> where exactly the time is spent. If you're running on a Linux system,
> I'd suggest using 'perf' to capture a trace of the backend functions
> where the time is spent:
>
> 1. Open a psql session. Run "select pg_backend_pid();" to get the
> backend's PID
>
> 2. In another terminal, launch "perf record -g -p <pid>".
>
> 3. Run the EXPLAIN in a loop:
>
> \timing
> do $$
> begin
>    for i in 1..100000 loop
>    execute $query$
>      EXPLAIN SELECT kc.id AS rlrightid FROM child kc
>      WHERE NOT (EXISTS ( SELECT 1 FROM core
>                 WHERE kc.id = core.groupid));
>    $query$;
>    end loop;
> end;
> $$;
>
> 4. Quit psql, and run "perf report -g". It should print a detailed
> report on which parts of the system the CPU time is spent.
>
> > Also please note that below kind of query will executes million times in
> > our regular activities. So which might creating high CPU issue.
>
> Using a prepared statement would be a good idea in that case.
>
> - Heikki
>


-- 
Thanks & Regards,

Avinash.