Re: performance question (something to do w/ parameterized stmts?, wrong index types?)

What's EXPLAIN ANALYZE show?

On Mon, May 08, 2006 at 01:29:28PM -0400, Jeffrey Tenny wrote:
> Why does this query take so long?  (PostgreSQL 8.0.3, FC4)
> Hopefully I have provided enough information below.
>
> LOG:  statement: SELECT * FROM x WHERE f IN
> ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,\
>
$25,$26,$27,$28,$29,$30,$31,$32,$33,$34,$35,$36,$37,$38,$39,$40,$41,$42,$43,$44,$45,$46,$47,$48,$49,$50,$51,$52,$53,$54,$55,$56,$57,$58,$59,$60,$61,$62,$63\
>
,$64,$65,$66,$67,$68,$69,$70,$71,$72,$73,$74,$75,$76,$77,$78,$79,$80,$81,$82,$83,$84,$85,$86,$87,$88,$89,$90,$91,$92,$93,$94,$95,$96,$97,$98,$99,$100,$101,\
>
$102,$103,$104,$105,$106,$107,$108,$109,$110,$111,$112,$113,$114,$115,$116,$117,$118,$119,$120,$121,$122,$123,$124,$125,$126,$127,$128,$129,$130,$131,$132,\
>
$133,$134,$135,$136,$137,$138,$139,$140,$141,$142,$143,$144,$145,$146,$147,$148,$149,$150,$151,$152,$153,$154,$155,$156,$157,$158,$159,$160,$161,$162,$163,\
>
$164,$165,$166,$167,$168,$169,$170,$171,$172,$173,$174,$175,$176,$177,$178,$179,$180,$181,$182,$183,$184,$185,$186,$187,$188,$189,$190,$191,$192,$193,$194,\
>
$195,$196,$197,$198,$199,$200,$201,$202,$203,$204,$205,$206,$207,$208,$209,$210,$211,$212,$213,$214,$215,$216,$217,$218,$219,$220,$221,$222,$223,$224,$225,\
>
$226,$227,$228,$229,$230,$231,$232,$233,$234,$235,$236,$237,$238,$239,$240,$241,$242,$243,$244,$245,$246,$247,$248,$249,$250,$251,$252,$253,$254,$255,$256,\
>
$257,$258,$259,$260,$261,$262,$263,$264,$265,$266,$267,$268,$269,$270,$271,$272,$273,$274,$275,$276,$277,$278,$279,$280,$281,$282,$283,$284,$285,$286,$287,\
>
$288,$289,$290,$291,$292,$293,$294,$295,$296,$297,$298,$299,$300,$301,$302,$303,$304,$305,$306,$307,$308,$309,$310,$311,$312,$313,$314,$315,$316,$317,$318,\
>
$319,$320,$321,$322,$323,$324,$325,$326,$327,$328,$329,$330,$331,$332,$333,$334,$335,$336,$337,$338,$339,$340,$341,$342,$343,$344,$345,$346,$347,$348,$349,\
>
$350,$351,$352,$353,$354,$355,$356,$357,$358,$359,$360,$361,$362,$363,$364,$365,$366,$367,$368,$369,$370,$371,$372,$373,$374,$375,$376,$377,$378,$379,$380,\
>
$381,$382,$383,$384,$385,$386,$387,$388,$389,$390,$391,$392,$393,$394,$395,$396,$397,$398,$399,$400,$401,$402,$403,$404,$405,$406,$407,$408,$409,$410,$411,\
>
$412,$413,$414,$415,$416,$417,$418,$419,$420,$421,$422,$423,$424,$425,$426,$427,$428,$429,$430,$431,$432,$433,$434,$435,$436,$437,$438,$439,$440,$441,$442,\
>
$443,$444,$445,$446,$447,$448,$449,$450,$451,$452,$453,$454,$455,$456,$457,$458,$459,$460,$461,$462,$463,$464,$465,$466,$467,$468,$469,$470,$471,$472,$473,\
>
$474,$475,$476,$477,$478,$479,$480,$481,$482,$483,$484,$485,$486,$487,$488,$489,$490,$491,$492,$493,$494,$495,$496,$497,$498,$499,$500,$501,$502,$503,$504,\
>
$505,$506,$507,$508,$509,$510,$511,$512,$513,$514,$515,$516,$517,$518,$519,$520,$521,$522,$523,$524,$525,$526,$527,$528,$529,$530,$531,$532,$533,$534,$535,\
>
$536,$537,$538,$539,$540,$541,$542,$543,$544,$545,$546,$547,$548,$549,$550,$551,$552,$553,$554,$555,$556,$557,$558,$559,$560,$561,$562,$563,$564,$565,$566,\
>
$567,$568,$569,$570,$571,$572,$573,$574,$575,$576,$577,$578,$579,$580,$581,$582,$583,$584,$585,$586,$587,$588,$589,$590,$591,$592,$593,$594,$595,$596,$597,\
>
$598,$599,$600,$601,$602,$603,$604,$605,$606,$607,$608,$609,$610,$611,$612,$613,$614,$615,$616,$617,$618,$619,$620,$621,$622,$623,$624,$625,$626,$627,$628,\
> $629,$630,$631,$632,$633,$634,$635,$636,$637,$638,$639,$640,$641,$642,$643,$644,$645,$646,$647,$648,$649,$650)
> ORDER BY f,c
>
> LOG:  EXECUTOR STATISTICS
> DETAIL:  ! system usage stats:
>         !       10.282945 elapsed 10.234444 user 0.048992 system sec
>         !       [25.309152 user 0.500923 sys total]
>         !       0/0 [0/0] filesystem blocks in/out
>         !       0/0 [0/10397] page faults/reclaims, 0 [0] swaps
>         !       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
>         !       0/15 [291/55] voluntary/involuntary context switches
>         ! buffer usage stats:
>         !       Shared blocks:          0 read,          0 written,
> buffer hit rate = 100.00%
>         !       Local  blocks:          0 read,          0 written,
> buffer hit rate = 0.00%
>         !       Direct blocks:          0 read,          0 written
>
>
> Here is the table description:
>
> Table "public.x"
>  Column |  Type   | Modifiers
> --------+---------+-----------
>  f      | integer | not null
>  c      | integer | not null
>  r      | integer | not null
>  n      | integer | not null
> Indexes:
>     "x_c_idx" btree (c)
>     "x_f_idx" btree (f)
>     "testindex2" btree (f, c)
>
>
> There are only 2,369 records in the X table.
>
> I don't understand why this query should take 10 seconds in the executor
> phase, with so little data being managed, and all relevant data already
> in memory.  Any clues?
>
> Maybe there are more database server debugging options I should have
> tweaked, but I'm not sure what.  The stuff I turned on included:
>
> log_duration = true
> log_statement = 'all'
> log_parser_stats = true
> log_planner_stats = true
> log_executor_stats = true
>
>   (N.B. log_statement_stats = true caused the server startup failure
> every time with no error message I could find, so was not deliberately set)
>
> stats_start_collector = true
> stats_command_string = true
> stats_block_level = true
> stats_row_level = true
> stats_reset_on_server_start = true
>
>
>
> (FYI: 10 secs is a lot only because this query is executed many times in
> my application, and they're pretty much all bad, and the aggregate query
> times are killing my app response).
>
> Thanks for any tips!
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

--
Jim C. Nasby, Sr. Engineering Consultant      jnasby@pervasive.com
Pervasive Software      http://pervasive.com    work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf       cell: 512-569-9461