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 <hlinnaka(at)iki(dot)fi> 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.