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

2008/1/7, Greg Smith <gsmith@gregsmith.com>:
> On Mon, 7 Jan 2008, Clodoaldo wrote:
>
> > I just did it. Built and installed 8.2.5. Copied the postgresql.conf
> > from the production. Issued an analyze and ran the insert query twice:
> > The second time it ran in 403 sec, half the production time.
>
> OK, you're getting close now.  What you should do now is run your query on
> 8.2.5 with EXPLAIN ANALYZE (the sample you gave before had just EXPLAIN),
> run it again on that same server with 8.3, then post the two plans.  Now
> that it's a fair comparision looking at the differences between the two
> should give an idea of the cause.

The two following queries ran in this server spec:
Fedora 8, Core Duo 2.33 MHz, 4 GB mem, two 7200 sata disks in Raid 1.

$ uname -a
Linux s1 2.6.23.9-85.fc8 #1 SMP Fri Dec 7 15:49:36 EST 2007 x86_64
x86_64 x86_64 GNU/Linux

Insert query with 8.2.5, default xlog_seg_size:

fahstats=> explain analyze
fahstats-> insert into usuarios (
fahstats(>   data,
fahstats(>   usuario,
fahstats(>   pontos,
fahstats(>   wus
fahstats(>   )
fahstats->   select
fahstats->     (select data_serial from data_serial) as data,
fahstats->     ui.usuario_serial as usuario,
fahstats->     sum(pontos) as pontos,
fahstats->     sum(wus) as wus
fahstats->   from usuarios_temp as ut inner join usuarios_indice as ui
fahstats->     on ut.usuario = ui.usuario_nome and ut.n_time = ui.n_time
fahstats->   group by data, ui.usuario_serial
fahstats->   ;

        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)
         InitPlan
           ->  Seq Scan on data_serial  (cost=0.00..1.01 rows=1
width=4) (actual time=0.006..0.006 rows=1 loops=1)
         ->  Merge Join  (cost=102546.09..267675.46 rows=5841302
width=12) (actual time=5173.428..10674.007 rows=886533 loops=1)
               Merge Cond: ((ut.n_time = ui.n_time) AND
((ut.usuario)::text = "inner"."?column4?"))
               ->  Index Scan using usuarios_temp_ndx on usuarios_temp
ut  (cost=0.00..58476.33 rows=886533 width=26) (actual
time=0.093..2493.622 rows=886533 loops=1)
               ->  Sort  (cost=102546.09..104747.98 rows=880756
width=22) (actual time=5173.315..5470.835 rows=886573 loops=1)
                     Sort Key: ui.n_time, (ui.usuario_nome)::text
                     ->  Seq Scan on usuarios_indice ui
(cost=0.00..15578.56 rows=880756 width=22) (actual time=0.023..364.002
rows=880731 loops=1)
 Trigger for constraint datas: time=14231.240 calls=880691
 Total runtime: 356862.302 ms
(12 rows)

Time: 357750.531 ms


Same insert query with 8.3-beta4, default xlog_seg_size:


        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)
         InitPlan
           ->  Seq Scan on data_serial  (cost=0.00..1.01 rows=1
width=4) (actual time=0.009..0.010 rows=1 loops=1)
         ->  Merge Join  (cost=101792.68..259032.28 rows=5711219
width=12) (actual time=4299.239..9645.146 rows=883729 loops=1)
               Merge Cond: ((ut.n_time = ui.n_time) AND
((ut.usuario)::text = (ui.usuario_nome)::text))
               ->  Index Scan using usuarios_temp_ndx on usuarios_temp
ut  (cost=0.00..52880.46 rows=883729 width=23) (actual
time=0.097..2164.406 rows=883729 loops=1)
               ->  Sort  (cost=101792.68..103987.58 rows=877958
width=19) (actual time=4299.116..4604.372 rows=883769 loops=1)
                     Sort Key: ui.n_time, ui.usuario_nome
                     Sort Method:  quicksort  Memory: 90120kB
                     ->  Seq Scan on usuarios_indice ui
(cost=0.00..15121.58 rows=877958 width=19) (actual time=0.028..297.058
rows=877935 loops=1)
 Trigger for constraint datas: time=33179.197 calls=877895
 Total runtime: 9546878.520 ms
(13 rows)

Time: 9547801.116 ms

Regards, Clodoaldo Pinto Neto