Planning time is high in Postgres 11.5 Compared with Postgres 10.11

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

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&amp;a=commitdiff&amp;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

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&amp;a=commitdiff&amp;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.

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

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
<http://libc-2.17.so>           [.] __vsnprintf_chk+    4.62%     1.52%
 postgres  libc-2.17.so <http://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.

ú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
<http://libc-2.17.so>           [.] __vsnprintf_chk+    4.62%     1.52%
postgres  libc-2.17.so <http://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

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
<http://libc-2.17.so>           [.] __vsnprintf_chk+    4.62%     1.52%
postgres  libc-2.17.so <http://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.

ú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

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

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

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