vacuum analyze slows sql query

Greetings pgsql-sql,

I have a very strange problem.  Our production database is a fair
sized db, structure wise, and quite huge data wise.  We have a web/php
based UI for our customer to manage the data in our application db.
The customer complains that the UI is sluggish accessing certain
pages and completely times-out on certain other pages.

We have a nightly "garbage collection" process that runs and purges
any old data.  After this process a 'vacuum analyze' is kicked off
(regardless of whether or not any data was actually purged).

At this point I should mention that our customer sites are running
PostgreSQL 7.1.3; however, I am able to reproduce the issue on 7.4.2.
If it at all matters, customer is running the db on a Dell PowerEdge
2550 equiped with 1gig of ram. My personal test box is a 700Mhz Intel
with 512mb ram.

I have in the past made modifications to our SQL statements to make
queries more efficient.  At this point I have given up and set out
to strip down our database and data enough to be able to post to
the list and ask for help from more qualified SQL experts.

In the process of "stripping down" our database I noticed some very
strange behavior which I could not explain.  I started to reformulate
my original to-be post to to the list to ask assistence in explaining
this strange behavior I was observing.  Next I noticed yet another
strange issue with PostgreSQL.

I noticed that a freshly created db with freshly inserted data (from
a previous pg_dump) would result in quite fast results.  However,
after running 'vacuum analyze' the very same query slowed down about
1250x (Time: 1080688.921 ms vs Time: 864.522 ms).

Following is a paste from a psql shell after a dropdb, createdb
and populate db.  The query is fast.  I next run 'explain' and 'explain
verbose' on the query.  Then you see a 'vacuum analyze' followed by
the the 'explain', 'explain verbose' and lastly the query again which
is now extremely slow!


------ begin
orig=# select offer_id, pkk_offer_has_pending_purch( offer_id ) from pkk_offer
;
<ommiting output />
(618 rows)

Time: 864.522 ms
orig=# explain select offer_id, pkk_offer_has_pending_purch( offer_id ) from
pkk_offer ;                        QUERY PLAN
-------------------------------------------------------------Seq Scan on pkk_offer  (cost=0.00..22.50 rows=1000
width=4)
(1 row)

Time: 24.251 ms
orig=# explain verbose select offer_id, pkk_offer_has_pending_purch( offer_id )
from pkk_offer ;
                        QUERY PLAN
-------------------------------------------------------------   {SEQSCAN    :startup_cost 0.00    :total_cost 22.50
:plan_rows1000    :plan_width 4    :targetlist (      {TARGETENTRY       :resdom          {RESDOM          :resno 1
    :restype 23          :restypmod -1          :resname offer_id          :ressortgroupref 0          :resorigtbl
34965071         :resorigcol 1          :resjunk false         }             :expr          {VAR          :varno 1
   :varattno 1          :vartype 23          :vartypmod -1          :varlevelsup 0          :varnoold 1
:varoattno1         }      }          {TARGETENTRY       :resdom          {RESDOM          :resno 2          :restype
16         :restypmod -1          :resname pkk_offer_has_pending_purch          :ressortgroupref 0          :resorigtbl
0         :resorigcol 0          :resjunk false         }             :expr          {FUNCEXPR          :funcid
34965096         :funcresulttype 16          :funcretset false          :funcformat 0          :args (            {VAR
          :varno 1             :varattno 1             :vartype 23             :vartypmod -1             :varlevelsup 0
           :varnoold 1             :varoattno 1            }         )         }      }   )       :qual <>    :lefttree
<>   :righttree <>    :initPlan <>    :extParam ()       :allParam ()       :nParamExec 0    :scanrelid 1   }Seq Scan
onpkk_offer  (cost=0.00..22.50 rows=1000 width=4)
 
(78 rows)

Time: 10.915 ms
orig=# vacuum analyze ;
VACUUM
Time: 504701.795 ms
orig=# explain select offer_id, pkk_offer_has_pending_purch( offer_id ) from
pkk_offer ;                        QUERY PLAN
------------------------------------------------------------Seq Scan on pkk_offer  (cost=0.00..13.72 rows=618 width=4)
(1 row)

Time: 96.903 ms
orig=# explain verbose select offer_id, pkk_offer_has_pending_purch( offer_id )
from pkk_offer ;                        QUERY PLAN
------------------------------------------------------------   {SEQSCAN    :startup_cost 0.00    :total_cost 13.72
:plan_rows618    :plan_width 4    :targetlist (      {TARGETENTRY       :resdom          {RESDOM          :resno 1
   :restype 23          :restypmod -1          :resname offer_id          :ressortgroupref 0          :resorigtbl
34965071         :resorigcol 1          :resjunk false         }             :expr          {VAR          :varno 1
   :varattno 1          :vartype 23          :vartypmod -1          :varlevelsup 0          :varnoold 1
:varoattno1         }      }          {TARGETENTRY       :resdom          {RESDOM          :resno 2          :restype
16         :restypmod -1          :resname pkk_offer_has_pending_purch          :ressortgroupref 0          :resorigtbl
0         :resorigcol 0          :resjunk false         }             :expr          {FUNCEXPR          :funcid
34965096         :funcresulttype 16          :funcretset false          :funcformat 0          :args (            {VAR
          :varno 1             :varattno 1             :vartype 23             :vartypmod -1             :varlevelsup 0
           :varnoold 1             :varoattno 1            }         )         }      }   )       :qual <>    :lefttree
<>   :righttree <>    :initPlan <>    :extParam ()       :allParam ()       :nParamExec 0    :scanrelid 1   }Seq Scan
onpkk_offer  (cost=0.00..13.72 rows=618 width=4)
 
(78 rows)

Time: 2.207 ms
orig=# select offer_id, pkk_offer_has_pending_purch( offer_id ) from pkk_offer
;
<ommiting output />
(618 rows)

Time: 1080688.921 ms
------ end


Has anyone seen something like this before?  Is this standard,
expected behavior?


The .sql file that will create the tables and stored function
follows.  It has been processed by uuencode to avoid Yahoo! mail
wrapping lines and messing things up.

The data that I'm testing this db with is somewhat large; even in
its "stripped down," "sanatized" and gzip'ed form:

% ls -lG --si pkk.20041028_00.sql.gz 
-rw-r--r--    1 patrick       17M Oct 28 18:15 pkk.20041028_00.sql.gz


I can email the data file, split(1) in multiple chunks, to anyone
interested in looking into this problem.  I may be able to provide an
http (or possibly an ftp) link for downloading it for a short period
of time.  I can't have the http link up permanently as I am limited
bandwith wise.  By far emailing would be my prefered method.


Thanks for reading,
--patrick


begin 644 pkk_db.sql
M+RHJ"B`J("1)9#H@)`H@*@H@*B!#;W!Y<FEG:'0@*&,I(#(P,#0@<&%T<FEC
M:R!K97-H:7-H:6%N"B`J"B`J(%1H:7,@:7,@82`B;6EM:6-E9"(@9&%T86)A
M<V4@=&\@<F5P;&EC871E(&$@<VQO=R!344P@=VET:&]U=`H@*B!D:79A=6QG
M:6YG('1O;R!M=6-H(&%B;W5T('1H92!I;G1E<FYA;"!D871A(&]F('1H92!O
M<FEG:6YA;`H@*B!D871A8F%S92!I;B!P<F]D=6-T:6]N('-Y<W1E;7,N"B`J
M+PH*+RHJ"B`J($1R;W`@=&%B;&5S(&%N9"!D871A8F%S92!E;&5M96YT<R!F
M:7)S="`N+BX*("HO"F1R;W`@9G5N8W1I;VX@<&MK7V]F9F5R7VAA<U]P96YD
M:6YG7W!U<F-H*"!I;G1E9V5R("D@.PID<F]P(&9U;F-T:6]N('!K:U]O9F9E
M<E]H87-?<&5N9&EN9U]P=7)C:#(H(&EN=&5G97(@*2`["F1R;W`@=&%B;&4@
M<&MK7V)I;&QI;F<@.PID<F]P('1A8FQE('!K:U]P=7)C:&%S92`["F1R;W`@
M=&%B;&4@<&MK7V]F9F5R(#L*"B\J*@H@*B!#<F5A=&4@=&%B;&5S(&%N9"!O
M=&AE<B!D871A8F%S92!E;&5M96YT<R`N+BX*("HO"F-R96%T92!T86)L90IP
M:VM?;V9F97(*("`@("@*("`@(&]F9F5R7VED("`@("`@("!I;G1E9V5R("`@
M("!P<FEM87)Y(&ME>2P*("`@(&1E<V-R:7!T:6]N("`@("!T97AT"B`@("`I
M(#L*"F-R96%T92!T86)L90IP:VM?<'5R8VAA<V4*("`@("@*("`@('!U<F-H
M87-E7VED("`@("!I;G1E9V5R("`@("!N;W0@;G5L;"P*("`@(&-L:65N=%]I
M9"`@("`@("!V87)C:&%R*#(P*2!N;W0@;G5L;"P*("`@(&]F9F5R7VED("`@
M("`@("!I;G1E9V5R("`@("!N;W0@;G5L;"P@+2T@9F]R96EG;B!K97D*("`@
M(&5X<&ER95]T:6UE("`@("!T:6UE<W1A;7`@=VET:&]U="!T:6UE('IO;F4L
M"B`@("!C86YC96Q?9&%T92`@("`@=&EM97-T86UP('=I=&AO=70@=&EM92!Z
M;VYE+`H@("`@<&5N9&EN9R`@("`@("`@(&)O;VQE86XL"@H@("`@<')I;6%R
M>2!K97DH('!U<F-H87-E7VED+"!C;&EE;G1?:60@*2P*"B`@("!C;VYS=')A
M:6YT(&9K7W!U<E]O9F9E<E]I9`H@("`@("`@(&9O<F5I9VX@:V5Y("@@;V9F
M97)?:60@*0H@("`@("`@("`@("!R969E<F5N8V5S('!K:U]O9F9E<B@@;V9F
M97)?:60@*0H@("`@*2`["F-R96%T92!I;F1E>"!P=7)?;V9F97)?:61?:61X
M(&]N('!K:U]P=7)C:&%S92@@;V9F97)?:60@*3L*8W)E871E(&EN9&5X('!U
M<E]E>'!I<F5?=&EM95]I9'@@;VX@<&MK7W!U<F-H87-E*"!E>'!I<F5?=&EM
M92`I.PIC<F5A=&4@:6YD97@@<'5R7W!E;F1I;F=?:61X(&]N('!K:U]P=7)C
M:&%S92@@<&5N9&EN9R`I.PH*8W)E871E('1A8FQE"G!K:U]B:6QL:6YG"B`@
M("`H"B`@("!P=7)C:&%S95]I9"`@("`@:6YT96=E<B`@("`@;F]T(&YU;&PL
M("TM(&9O<F5I9VX@:V5Y"B`@("!C;&EE;G1?:60@("`@("`@=F%R8VAA<B@R
M,"D@;F]T(&YU;&PL("TM(&1I='1O"B`@("!P96YD:6YG("`@("`@("`@8F]O
M;&5A;BP*"B`@("!C;VYS=')A:6YT(&9K7V)I;%]P=7)?:60*("`@("`@("!F
M;W)E:6=N(&ME>2`H('!U<F-H87-E7VED+"!C;&EE;G1?:60@*0H@("`@("`@
M("`@("!R969E<F5N8V5S('!K:U]P=7)C:&%S92@@<'5R8VAA<V5?:60L(&-L
M:65N=%]I9"`I"B`@("`I(#L*8W)E871E(&EN9&5X(&)I;%]P96YD:6YG7VED
M>"!O;B!P:VM?8FEL;&EN9R@@<&5N9&EN9R`I.PH*"B\J*@H@*B!,971S(&-R
M96%T92!O=7(@9G5N8W1I;VYS("XN+@H@*B\*+RHJ"B`J(%!U<F-H87-E(&ES
M('!E;F1I;F<@:68@86YY(&]F('1H92!F;VQL;W=I;F<@8V]N9&ET:6]N<R!H
M;VQD('1R=64Z"B`J("!A+B!P96YD:6YG(&9I96QD(&ES('-E="!T;R!T<G5E
M("U/4BT*("H@(&(N(&-A8VYE;%]D871E(&ES($Y53$P@*&DN92XL(&YO="!C
M86YC;&QE9"D@+4%.1"T*("H@("`@("!I+B!E>'!I<F5?=&EM92!I<R!I;B!T
M:&4@9G5T=7)E("U/4BT*("H@("`@(&EI+B!E>'!I<F5?=&EM92!I<R!.54Q,
M("AI+F4N+"!A(')E8W5R<FEN9R!P=7)C:&%S92]S=6)S8W)I<'1I;VXI"B`J
M+PIC<F5A=&4@9G5N8W1I;VX*<&MK7V]F9F5R7VAA<U]P96YD:6YG7W!U<F-H
M*"!I;G1E9V5R("D*("`@(')E='5R;G,@8F]O;`IA<R`@)PH@("`@<V5L96-T
M("!C87-E"B`@("`@("`@("`@('=H96X*("`@("`@("`@("`@("`@("@*("`@
M("`@("`@("`@("`@('-E;&5C="`@<#`N<'5R8VAA<V5?:60*("`@("`@("`@
M("`@("`@("`@9G)O;2`@<&MK7W!U<F-H87-E('`P"B`@("`@("`@("`@("`@
M("`@=VAE<F4@('`P+F]F9F5R7VED(#T@)#$*("`@("`@("`@("`@("`@("`@
M("`@("`@86YD("@@<#`N<&5N9&EN9R`]('1R=64*("`@("`@("`@("`@("`@
M("`@("`@("`@("`@(&]R("@@*"!P,"YE>'!I<F5?=&EM92`^(&YO=R@I"B`@
M("`@("`@("`@("`@("`@("`@("`@("`@("`@("`@(&]R('`P+F5X<&ER95]T
M:6UE(&ES;G5L;"`I"B`@("`@("`@("`@("`@("`@("`@("`@("`@("`@("!A
M;F0@<#`N8V%N8V5L7V1A=&4@:7-N=6QL("D@*0H@("`@("`@("`@("`@("`@
M("!L:6UI="`Q"B`@("`@("`@("`@("`@("`I"B`@("`@("`@("`@("`@("!I
M<VYU;&P*("`@("`@("`@("`@=&AE;B!F86QS90H@("`@("`@("`@("!E;'-E
M('1R=64*("`@("`@("`@("`@96YD(#L*)R!L86YG=6%G92`G<W%L)R`["@H*
M+RHJ"B`J(%1H:7,@9G5N8W1I;VX@9VEV97,@=V]R<V4@<&5R9F]R;6%N8V4@
M=&EM92X@($ET('=A<R!C<F5A=&5D"B`J(&9O<B!T97-T('!U<G!O<V5S(&]N
M;'DN"B`J+PIC<F5A=&4@9G5N8W1I;VX*<&MK7V]F9F5R7VAA<U]P96YD:6YG
M7W!U<F-H,B@@:6YT96=E<B`I"B`@("!R971U<FYS(&)O;VP*87,@("<*("`@
M('-E;&5C="`@*"!C;W5N="@J*2`^(#`@*3HZ8F]O;`H@("`@("!F<F]M("!P
M:VM?<'5R8VAA<V4@<#`*("`@("!W:&5R92`@<#`N;V9F97)?:60@/2`D,0H@
M("`@("`@("`@("!A;F0@*"!P,"YP96YD:6YG(#T@=')U90H@("`@("`@("`@
M("`@("`@;W(@*"`H('`P+F5X<&ER95]T:6UE(#X@;F]W*"D*("`@("`@("`@
M("`@("`@("`@("`@;W(@<#`N97AP:7)E7W1I;64@:7-N=6QL("D*("`@("`@
M("`@("`@("`@("`@(&%N9"!P,"YC86YC96Q?9&%T92!I<VYU;&P@*2`I"B`@
7("`["B<@;&%N9W5A9V4@)W-Q;"<@.PH`
`
end

    
__________________________________ 
Do you Yahoo!? 
Check out the new Yahoo! Front Page. 
www.yahoo.com