Re: ATTN: Clodaldo was Performance problem. Could it be related to 8.3-beta4?

"Scott Marlowe" <scott.marlowe@gmail.com> writes:
> OK, I was looking at the previous thread that you thought had
> disappeared, and with the explain analyze output from 8.3 I noticed
> something odd.

> For 8.2 you had something like this:

>       QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Subquery Scan "*SELECT*"  (cost=326089.49..350310.28 rows=880756
> width=20) (actual time=11444.566..13114.365 rows=880691 loops=1)
>    ->  HashAggregate  (cost=326089.49..339300.83 rows=880756 width=12)
> (actual time=11444.554..12438.188 rows=880691 loops=1)
> ... SNIP ...
> Time: 357750.531 ms

> And for 8.3 you had something like this:
>       QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Subquery Scan "*SELECT*"  (cost=316145.48..340289.33 rows=877958
> width=20) (actual time=10650.036..12997.377 rows=877895 loops=1)
>    ->  HashAggregate  (cost=316145.48..329314.85 rows=877958 width=12)
> (actual time=10650.023..12193.890 rows=877895 loops=1)
> ... SNIP ...
> Time: 9547801.116 ms

> In both of those instances, the actual time used is WAY larger than
> the time listed in the explain analyze, which has usually pointed to a
> very expensive OS level get time of day call.

No, that's not it --- these last two runs are on the same OS.

Remember this command is an INSERT/SELECT.  The total actual time for
the SELECT part of it (ie, forming the rows to insert) is what's
reported as the top-level plan node's runtime --- so 8.3 is actually a
shade faster than 8.2 here.  And separately from that we can see the
time spent in the one foreign-key trigger, which seems to be slower on
8.3, but neither of these are where the majority of the runtime is
going.  The rest of the runtime must be spent in the physical data
insertion --- storing the rows, updating the indexes, and/or writing
WAL.  I don't see any particular reason for that to be so much worse in
8.3; especially not for such a simple table definition:
http://archives.postgresql.org/pgsql-general/2008-01/msg00266.php

There's something awfully weird going on there.  I can replicate some
slowdown from 8.2 to 8.3, which should be looked into, but it's not the
order-of-magnitude-worse that Clodaldo is getting.  I tried this simple
experiment, which should be at least comparable to his table structure:

create table foo (f1 int, f2 int, f3 int, f4 real);
create index fooi on foo(f1);
create index fooi2 on foo(f2);
explain analyze insert into foo select i,i,0,1.0 from generate_series(1,1000000) i;

and repeated the last a few times.  On 8.2.6 I get numbers like this:

regression=# explain analyze insert into foo select i,i,0,1.0 from generate_series(1,1000000) i;
                                                          QUERY PLAN
       

-------------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000 width=4) (actual time=419.101..1408.868 rows=1000000
loops=1)
 Total runtime: 16783.096 ms
(2 rows)

regression=# explain analyze insert into foo select i,i,0,1.0 from generate_series(1,1000000) i;
                                                          QUERY PLAN
       

-------------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000 width=4) (actual time=421.440..1512.787 rows=1000000
loops=1)
 Total runtime: 18785.652 ms
(2 rows)

8.3RC1 gives numbers more like this:

regression=# explain analyze insert into foo select i,i,0,1.0 from generate_series(1,1000000) i;
                                                          QUERY PLAN
       

-------------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000 width=4) (actual time=420.742..1872.290 rows=1000000
loops=1)
 Total runtime: 17278.170 ms
(2 rows)

regression=# explain analyze insert into foo select i,i,0,1.0 from generate_series(1,1000000) i;
                                                          QUERY PLAN
       

-------------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000 width=4) (actual time=435.392..1909.631 rows=1000000
loops=1)
 Total runtime: 20673.453 ms
(2 rows)

This is my usual debugging setup, built --enable-debug --enable-cassert
but with "SET debug_assertions = 0" so that shouldn't affect things too much,
no configuration changes from what initdb gave me except fsync = off
(so it's not too representative of real-world performance, maybe).

It would be interesting to see the identical test on Clodaldo's
installations.

            regards, tom lane