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

2008/1/16, Tom Lane <tgl@sss.pgh.pa.us>:
> I went through this thread again, and noticed something that no one
> seems to have remarked on at the time: the vmstat numbers near the
> bottom of this post
>
> http://archives.postgresql.org/pgsql-general/2008-01/msg00161.php
>
> show close to 100% I/O wait time (either that or 50% idle 50% I/O wait,
> which I suspect is an artifact).  We subsequently concluded that the
> "SELECT" side of the INSERT/SELECT command is not where the problem is,
> so all the cycles are going into the actual row insertion part.
>
> I don't know of any reason to think that insertion is slower in 8.3
> than it was in 8.2, and no one else has reported anything of the sort.
> So I'm leaning to the idea that this suggests some kind of
> misconfiguration of the disk setup in Clodoaldo's new server.  There
> was some earlier discussion about not having the RAID configured right:

Now it is tested in this configuration, the old server:

Fedora Core 6, AMD XP2600, 2 GB mem, two
7200 ide disks with pg_xlog alone in the second disk.

This is 8.2.6:

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=307438.81..331782.20 rows=885214
width=20) (actual time=31433.335..35989.973 rows=885281 loops=1)
  ->  HashAggregate  (cost=307438.81..320717.02 rows=885214 width=12)
(actual time=31433.318..33886.039 rows=885281 loops=1)
        InitPlan
          ->  Seq Scan on data_serial  (cost=0.00..1.01 rows=1
width=4) (actual time=0.016..0.018 rows=1 loops=1)
        ->  Merge Join  (cost=102838.10..254834.62 rows=5260318
width=12) (actual time=12146.535..29242.146 rows=891140 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..55486.37 rows=891140 width=26) (actual
time=0.217..8457.332 rows=891140 loops=1)
              ->  Sort  (cost=102838.10..105051.14 rows=885214
width=22) (actual time=12146.264..13215.173 rows=891180 loops=1)
                    Sort Key: ui.n_time, (ui.usuario_nome)::text
                    ->  Seq Scan on usuarios_indice ui
(cost=0.00..15398.14 rows=885214 width=22) (actual
time=0.055..1266.373 rows=885321 loops=1)
Trigger for constraint datas: time=28494.257 calls=885281
Total runtime: 824920.034 ms
(12 rows)
Time: 825219.242 ms

8.3RC1:

QUERY PLAN
Subquery Scan "*SELECT*"  (cost=315346.40..339490.66 rows=877973
width=20) (actual time=28527.088..34628.084 rows=877895 loops=1)
  ->  HashAggregate  (cost=315346.40..328516.00 rows=877973 width=12)
(actual time=28527.060..32082.655 rows=877895 loops=1)
        InitPlan
          ->  Seq Scan on data_serial  (cost=0.00..1.01 rows=1
width=4) (actual time=0.018..0.021 rows=1 loops=1)
        ->  Merge Join  (cost=101200.86..257473.27 rows=5787212
width=12) (actual time=9796.697..25537.218 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..50587.20 rows=883729 width=23) (actual
time=0.254..6940.743 rows=883729 loops=1)
              ->  Sort  (cost=101199.42..103394.35 rows=877973
width=19) (actual time=9796.386..10962.868 rows=883769 loops=1)
                    Sort Key: ui.n_time, ui.usuario_nome
                    Sort Method:  quicksort  Memory: 63286kB
                    ->  Seq Scan on usuarios_indice ui
(cost=0.00..14526.73 rows=877973 width=19) (actual
time=0.080..1158.713 rows=877935 loops=1)
Trigger for constraint datas: time=44379.117 calls=877895
Total runtime: 8865110.176 ms
(13 rows)
Time: 8865629.601 ms

Both versions where analized before running.

The old server reproduces the behavior of the new one.

Regards, Clodoaldo Pinto Neto