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

2008/1/10, Tom Lane <tgl@sss.pgh.pa.us>:
> "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.

This is 8.2.6 in the new server:

cpn=> create table foo (f1 int, f2 int, f3 int, f4 real);
CREATE TABLE
cpn=> create index fooi on foo(f1);
CREATE INDEX
cpn=> create index fooi2 on foo(f2);
CREATE INDEX
cpn=> 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=270.425..699.067 rows=1000000 loops=1)
  Total runtime: 12888.913 ms
(2 rows)

The table into which I'm inserting 800 thousand rows, usuarios, has
135 million rows so I did:

cpn=> explain analyze insert into foo select i,i,0,1.0 from
generate_series(1,135500000) i;

                                                             QUERY
PLAN

-------------------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000
width=4) (actual time=49852.161..403976.519 rows=135500000 loops=1)
  Total runtime: 2044745.294 ms
(2 rows)
cpn=> analyze;
...warnings...
ANALYZE
cpn=> explain analyze insert into foo select i,i,0,1.0 from
generate_series(135500001, 135500000 + 800000 ) i;
                                                         QUERY PLAN

-----------------------------------------------------------------------------------------------------------------------------
 Function Scan on generate_series i  (cost=0.00..12.50 rows=1000
width=4) (actual time=196.804..553.617 rows=800000 loops=1)
  Total runtime: 11202.895 ms
(2 rows)

The real table has foreign keys. Don't it make a difference?

I can reinstall 8.3 and try it. Will it be necessary or interesting?
beta4 or RC1?

Regards, Clodoaldo Pinto Neto