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

2008/1/7, Greg Smith <gsmith(at)gregsmith(dot)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