Re: Planning time is high in Postgres 11.5 Compared with Postgres 10.11 - Mailing list pgsql-bugs
| From | avinash varma |
|---|---|
| Subject | Re: Planning time is high in Postgres 11.5 Compared with Postgres 10.11 |
| Date | |
| Msg-id | CADaHE9F1UKPwPeNvrkw_a-a7mkse_U3nVxRwwRfLekzaLj1ESw@mail.gmail.com Whole thread Raw |
| In response to | Re: Planning time is high in Postgres 11.5 Compared with Postgres10.11 (Heikki Linnakangas <hlinnaka@iki.fi>) |
| Responses |
Re: Planning time is high in Postgres 11.5 Compared with Postgres 10.11
|
| List | pgsql-bugs |
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:
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
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@iki.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.
pgsql-bugs by date: