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

Planning time is high in Postgres 11.5 Compared with Postgres 10.11

From

avinash varma

Date:

16 December 2019, 11:58:11

Hi Team,

We are planning upgrade our applications to Postgresql11.5 from Postgresql10.11.

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.

Also please note that below kind of query will executes million times in our regular activities. So which might creating high CPU issue.

Can you please help in resolving this issue. Also please let us know fix if you have already for this.

Notes:

1) All configuration parameters are identical in both 10.11 and 11.5(postgresql.conf is same).

2) Data is same in both versions.

3) Hardware of both versions are same.

4) we have executed explain analyze multiple times on the same session.

5) We are seeing this issue after performing vacuum full analyze after db restore to postgresql 11.5

Below is the test case which we performed to reproduce the issue.

Kindly let us know if you need any other information.

CREATE TABLE public.child
(
id bigint NOT NULL,
childid bigint NOT NULL
)
WITH (
OIDS = FALSE
)
TABLESPACE "PostDB";

CREATE INDEX child_index1 ON public.child USING btree (childid) TABLESPACE "PostDB";
CREATE UNIQUE INDEX child_primary ON public.child USING btree(id, childid) TABLESPACE "PostDB";

CREATE TABLE public.core
(
groupid bigint NOT NULL,
rightid bigint NOT NULL
)
WITH (
OIDS = FALSE
)
TABLESPACE "PostDB";

CREATE UNIQUE INDEX core_idx1 ON public.core USING btree (groupid, rightid) TABLESPACE "PostDB";

vacuum analyze child;
vacuum analyze core;

Postgres 10.5
=================
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));
QUERY PLAN
------------------------------------------------------------------------------------------------------------
Hash Anti Join (cost=51.62..116.08 rows=925 width=8) (actual time=0.007..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.006..0.006 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: 0.183 ms
Execution time: 0.041 ms
(7 rows)

Postgres 11.5, or 12.1
=================

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));
QUERY PLAN
------------------------------------------------------------------------------------------------------------
Hash Anti Join (cost=51.62..102.61 rows=1736 width=8) (actual time=0.005..0.005 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: 10.229 ms
Execution Time: 0.024 ms

Thanks & Regards,

Avinash.

Re: Planning time is high in Postgres 11.5 Compared with Postgres10.11

From

Heikki Linnakangas

Date:

16 December 2019, 15:23:58

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

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

From

avinash varma

Date:

16 December 2019, 17:30:39

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@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.

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

From

Tom Lane

Date:

16 December 2019, 18:10:07

avinash varma <avinashvarma443@gmail.com> writes:
> 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

Hm.  eqjoinsel didn't change at all between v10 and v11.  Are you
*sure* those installations have the same configurations?  A plausible
theory is that one has got a much larger default_statistics_target
than the other (or at least, did when these tables were last analyzed),
and in consequence these tables have large most-common-values
statistics arrays, but not in the v10 installation.

[ thinks for a bit ]  It seems possible that you could end up here
even if the user-level settings are indeed the same, as a result of

https://git.postgresql.org/gitweb/?p=postgresql.git&a=commitdiff&h=b5db1d93d

which changed the method for deciding which values are MCVs.  Maybe
these tables have some corner-case distribution that causes the new
method to think there are many more MCVs than the old one thought.

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

            regards, tom lane

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

From

avinash varma

Date:

16 December 2019, 18:27:20

Hi Tom,

Actually , we used the same backup to restore on both V10 & V11 , So the data on both the versions is same.
After restore, we ran vacuum full analyze on both the servers .

default_statistics_target value "1000" is same on both the versions.
Used the same postgresql.conf , i,e it is same on both V10 and V11

Thanks,

Avinash

On Mon, Dec 16, 2019 at 8:40 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

avinash varma <avinashvarma443@gmail.com> writes:
> 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

Hm. eqjoinsel didn't change at all between v10 and v11. Are you
*sure* those installations have the same configurations? A plausible
theory is that one has got a much larger default_statistics_target
than the other (or at least, did when these tables were last analyzed),
and in consequence these tables have large most-common-values
statistics arrays, but not in the v10 installation.

[ thinks for a bit ] It seems possible that you could end up here
even if the user-level settings are indeed the same, as a result of

https://git.postgresql.org/gitweb/?p=postgresql.git&a=commitdiff&h=b5db1d93d

which changed the method for deciding which values are MCVs. Maybe
these tables have some corner-case distribution that causes the new
method to think there are many more MCVs than the old one thought.

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

regards, tom lane

Thanks & Regards,

Avinash.

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

From

Tom Lane

Date:

16 December 2019, 19:16:54

avinash varma <avinashvarma443@gmail.com> writes:
> Actually , we used the same backup to restore on both V10 & V11  , So  the
> data on both the versions is same.
> After restore, we ran vacuum full analyze on both the servers .
> default_statistics_target  value "1000" is same on both the versions.
> Used the same postgresql.conf , i,e it is same on both V10 and V11

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 ...

Also, please don't top-post when replying.  It makes it hard for
people to follow the conversation.

            regards, tom lane

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

From

avinash varma

Date:

17 December 2019, 09:11:22

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

On Mon, Dec 16, 2019 at 9:46 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

avinash varma <avinashvarma443@gmail.com> writes:
> Actually , we used the same backup to restore on both V10 & V11 , So the
> data on both the versions is same.
> After restore, we ran vacuum full analyze on both the servers .
> default_statistics_target value "1000" is same on both the versions.
> Used the same postgresql.conf , i,e it is same on both V10 and V11

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 ...

Also, please don't top-post when replying. It makes it hard for
people to follow the conversation.

regards, tom lane

Thanks & Regards,

Avinash.

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

From

Pavel Stehule

Date:

17 December 2019, 09:19:30

út 17. 12. 2019 v 7:11 odesílatel avinash varma <avinashvarma443@gmail.com> napsal:

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

is same collation in both databases?

Maybe there are some issues in virtualization

Pavel

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

From

avinash varma

Date:

17 December 2019, 09:32:37

Hi Pavel,

Collation " en_US.UTF-8" is same on both databases. Infact both the v10 and V11 databases are on same machine.

Can you please let us know if i need to check anything..

Thanks,

Avinash

On Tue, Dec 17, 2019 at 11:50 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:

út 17. 12. 2019 v 7:11 odesílatel avinash varma <avinashvarma443@gmail.com> napsal:
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

is same collation in both databases?

Maybe there are some issues in virtualization

Pavel

Thanks & Regards,

Avinash.

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

From

Pavel Stehule

Date:

17 December 2019, 09:46:46

út 17. 12. 2019 v 7:32 odesílatel avinash varma <avinashvarma443@gmail.com> napsal:

Hi Pavel,

Collation " en_US.UTF-8" is same on both databases. Infact both the v10 and V11 databases are on same machine.

Can you please let us know if i need to check anything..

a) please don't send top post reply https://en.wikipedia.org/wiki/Posting_style - top posting is prohibited here

b) can you compare size of databases, indexes?

Pavel

Thanks,
Avinash

On Tue, Dec 17, 2019 at 11:50 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:

út 17. 12. 2019 v 7:11 odesílatel avinash varma <avinashvarma443@gmail.com> napsal:
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

is same collation in both databases?

Maybe there are some issues in virtualization

Pavel

--
Thanks & Regards,

Avinash.

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

From

avinash varma

Date:

17 December 2019, 14:34:18

>> b) can you compare size of databases, indexes?
I used the same backup to restore on V10 and V11 . So the no: of indexes and size of databases are same.

One observation is that after pg_restore, we are doing vacuum full analyze on both V10 and V11.

This is causing the slowness on V11 . Before vacuum analyze , same query is performing well on V11.

Is there any changes in the analyze script in V11 when compared to V10.

Thanks,

Avinash

Re: Planning time is high in Postgres 11.5 Compared with Postgres10.11

From

Tomas Vondra

Date:

17 December 2019, 15:07:51

On Tue, Dec 17, 2019 at 05:04:18PM +0530, avinash varma wrote:
>>> b) can you compare size of databases, indexes?
>I used the same backup  to restore on V10 and V11 . So the no: of indexes
>and size of databases are same.
>
>One observation is that after pg_restore, we are doing vacuum full analyze
>on both V10 and V11.
>
>This is causing the slowness on V11 . Before vacuum analyze , same query is
>performing well on V11.
>
>Is there any changes in the analyze script in V11 when compared to V10.
>

You've been asked (at least) twice to check size of statistics stored in
pg_stats. It's really hard to help you when you don't provide important
information like this.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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

From

Tom Lane

Date:

17 December 2019, 19:31:34

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:
> You've been asked (at least) twice to check size of statistics stored in
> pg_stats. It's really hard to help you when you don't provide important
> information like this.

Apparently we need to be more explicit.  What we want to see is

select most_common_vals from pg_stats
where tablename = 'child' and attname = 'id';

select most_common_vals from pg_stats
where tablename = 'core' and attname = 'groupid';

from both databases.  (Adjust as necessary if those weren't the
real table and column names.)  We probably don't need the specific
array elements, but we do want to know how big those arrays are.

            regards, tom lane