Обсуждение: 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

От
avinash varma
Дата:

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

От
Heikki Linnakangas
Дата:
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

От
avinash varma
Дата:
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

От
Tom Lane
Дата:
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

От
avinash varma
Дата:
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

От
Tom Lane
Дата:
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

От
avinash varma
Дата:
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

От
Pavel Stehule
Дата:


ú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

От
avinash varma
Дата:
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

От
Pavel Stehule
Дата:


ú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

От
avinash varma
Дата:
>> 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

От
Tomas Vondra
Дата:
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

От
Tom Lane
Дата:
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