Thread: slow query
OK, I've got a query that's running slow the first time, then fast. But I can't see where the time is really being spend on the first run. Query and plan attached to preserve formatting. The index scan and nested loop that feed the next layer up nested loop both show very short run times. Yet the nested loop they feed to takes 30 seconds to run. If I run the query a second time, everything looks the same but the second nested loop now runs in well under a second. I can't figure out where my time's going to.
Attachment
On Mon, Jan 12, 2009 at 2:59 PM, Scott Marlowe <scott.marlowe@gmail.com> wrote: > OK, I've got a query that's running slow the first time, then fast. > But I can't see where the time is really being spend on the first run. > Query and plan attached to preserve formatting. > > The index scan and nested loop that feed the next layer up nested loop > both show very short run times. Yet the nested loop they feed to > takes 30 seconds to run. If I run the query a second time, everything > looks the same but the second nested loop now runs in well under a > second. > > I can't figure out where my time's going to. If it is any help, there is a nice tool to format your explain plan at http://explain.depesz.com
Scott Marlowe wrote:
>
> OK, I've got a query that's running slow the first time, then fast.
> But I can't see where the time is really being spend on the first run.
> Query and plan attached to preserve formatting.
Often this is from caching -- the first time the system has to go to disk to get the values; the subsequent times the data (and indexes, presumably) are all in RAM and so much faster.
Is this plausible ?
Greg Williamson
Senior DBA
DigitalGlobe
Confidentiality Notice: This e-mail message, including any attachments, is for the sole use of the intended recipient(s) and may contain confidential and privileged information and must be protected in accordance with those provisions. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message.
(My corporate masters made me say this.)
"Scott Marlowe" <scott.marlowe@gmail.com> writes: > -> Index Scan using users_orgid_idx on users u (cost=0.00..129.52 rows=5 width=271) (actual time=843.825..860.638rows=0 loops=35) > Index Cond: (u.orgid = j2.orgid) > Filter: ((u.type_id < 10) AND (u.deleted = 0) AND ((lower((u.lname)::text) ~~ 'boat%'::text) OR (lower((u.fname)::text)~~ 'boat%'::text) OR (lower((u.username)::text) ~~ 'boat%'::text) OR (lower(u.option1) ~~ 'boat%'::text)OR (lower((u.email)::text) ~~ '%boat%'::text) OR (lower(u.external_id) = 'boat'::text))) Not sure if this is what's going on but I find the high startup time for this index scan suspicious. Either there are a lot of dead tuples (which would explain the second run being fast if it marks them all as lp_dead) or there are a lot of matching index pointers which fail those other constraints. Assuming it's the latter perhaps some other index definition would let it zero in on the right tuples more quickly instead of having to grovel through a lot of irrelevant rows? -- Gregory Stark EnterpriseDB http://www.enterprisedb.com Ask me about EnterpriseDB's Slony Replication support!
On Mon, Jan 12, 2009 at 5:59 PM, Scott Marlowe <scott.marlowe@gmail.com> wrote: > I can't figure out where my time's going to. Looks like it's going to: -> Index Scan using users_orgid_idx on users u (cost=0.00..129.52 rows=5 width=271) (actual time=843.825..860.638 rows=0 loops=35) I'd guess the index/pages for users isn't in memory the first time around. Next time is: -> Index Scan using users_orgid_idx on users u (cost=0.00..129.52 rows=5 width=271) (actual time=3.126..3.305 rows=0 loops=35) -- - David T. Wilson david.t.wilson@gmail.com
On Mon, Jan 12, 2009 at 4:55 PM, David Wilson <david.t.wilson@gmail.com> wrote: > On Mon, Jan 12, 2009 at 5:59 PM, Scott Marlowe <scott.marlowe@gmail.com> wrote: >> I can't figure out where my time's going to. > > Looks like it's going to: > > -> Index Scan using users_orgid_idx on users u (cost=0.00..129.52 > rows=5 width=271) (actual time=843.825..860.638 rows=0 loops=35) > > I'd guess the index/pages for users isn't in memory the first time around. Exactly. I keep forgetting to look at loops... sigh. Thanks!