Re: slow query - only uses indices

Hey Folks,

This query is running really slowly. Sometimes much slower then others. I
have a feeling that there may be contention on one of the indices it is
using. In the explain plan, it looks like it estimates 2 rows but actually
finds 228 rows? Is that really bad?

Query and explain plan are below. Seems like it spend the most time doing
Index Scan using i_tablea_atextfield on tablea ru
(cost=0.00..2265.28rows=2 width=12) (actual time=
0.624..881.313 rows=228 loops=1)

Any suggestions?

SELECT z.atextfield,
z.btextfield,
z.abigintfield,
p.achar255field, p.ptextfield,
z.achar1field, u.aboolfield,
z.textfield1,
z.achar8field,
z.achar16field
FROM tablea ru
INNER JOIN tableb u ON ( u.atextfield = ru.anothertextfield )
INNER JOIN tablec z ON u.atextfield = z.atextfield
INNER JOIN tabled p ON p.id = z.pid
LEFT JOIN tablee m ON u.atextfield = m.atextfield AND m.boolcol5
WHERE ru.atextfield = 'thelookupval'
AND u.boolcol1 IS TRUE
AND u.boolcol2 IS FALSE
AND ru.achar1field <> 'N'
AND ru.boolcol3 IS FALSE
AND NOT EXISTS ( SELECT 'x' FROM tablea fru WHERE fru.atextfield =
ru.anothertextfield AND fru.boolcol3 IS TRUE )
AND EXISTS ( SELECT 'x' FROM tablef s WHERE s.atextfield = ru.atextfieldAND
s.boolcol4 IS TRUE )
ORDER by ru.anothertextfield asc

Sort (cost=2341.96..2341.97 rows=2 width=146) (actual time=
1118.810..1119.098 rows=228 loops=1)
Sort Key: ru.anothertextfield
-> Nested Loop Left Join (cost=0.00..2341.95 rows=2 width=146) (actual
time= 0.930..1117.258 rows=228 loops=1)
-> Nested Loop (cost=0.00..2313.36 rows=2 width=131) (actual time=
0.842..914.554 rows=228 loops=1)
-> Nested Loop (cost=0.00..2296.65 rows=2 width=93) (actual
time= 0.765..901.916 rows=228 loops=1)
-> Nested Loop (cost=0.00..2281.98 rows=2 width=72)
(actual time=0.690..893.648 rows=228 loops=1)
-> Index Scan using i_tablea_atextfield on tablea
ru (cost= 0.00..2265.28 rows=2 width=12) (actual
time=0.624..881.313rows=228 loops=1)
Index Cond: (atextfield =
'thelookupval'::text)
Filter: ((achar1field <> 'N'::bpchar) AND
(boolcol3 IS FALSE) AND (NOT (subplan)) AND (subplan))
SubPlan
-> Index Scan using tablef_pkey on tablef
s (cost=0.00..8.34 rows=1 width=0) (actual time=0.016..0.016 rows=1
loops=228)
Index Cond: (atextfield = $1)
Filter: (boolcol4 IS TRUE)
-> Bitmap Heap Scan on tablea fru (cost=
4.61..90.41 rows=1 width=0) (actual time=3.590..3.590 rows=0 loops=243)
Recheck Cond: (atextfield = $0)
Filter: (boolcol3 IS TRUE)
-> Bitmap Index Scan on
i_tablea_atextfield (cost= 0.00..4.61 rows=22 width=0) (actual time=
0.044..0.044 rows=17 loops=243)
Index Cond: (atextfield = $0)
-> Index Scan using tablec_pkey on tablec z
(cost= 0.00..8.34 rows=1 width=60) (actual time=0.047..0.049 rows=1
loops=228)
Index Cond: (z.atextfield =
ru.anothertextfield)
-> Index Scan using tabled_pkey on tabled p (cost=
0.00..7.32 rows=1 width=29) (actual time=0.030..0.031 rows=1 loops=228)
Index Cond: (p.id = z.pid)
-> Index Scan using tableb_pkey on tableb u (cost=
0.00..8.34 rows=1 width=38) (actual time=0.049..0.051 rows=1 loops=228)
Index Cond: (u.atextfield = ru.anothertextfield)
Filter: ((boolcol1 IS TRUE) AND (boolcol2" IS FALSE))"
-> Index Scan using tablee_atextfield_idx on tablee m (cost=
0.00..14.28 rows=1 width=39) (actual time=0.883..0.883 rows=0 loops=228)
Index Cond: (u.atextfield = m.atextfield)

On Dec 24, 2007 7:46 PM, Marc <pgsql-general(at)mbreslow(dot)net> wrote:
> Hey Folks,
>
> This query is running really slowly. Sometimes much slower then others. I
> have a feeling that there may be contention on one of the indices it is
> using. In the explain plan, it looks like it estimates 2 rows but actually
> finds 228 rows? Is that really bad?
>

You should do an ANALYZE if actual rows are significantly different.
And they are.

>
>
> Query and explain plan are below. Seems like it spend the most time doing
> Index Scan using i_tablea_atextfield on tablea ru (cost=0.00..2265.28
> rows=2 width=12) (actual time=0.624..881.313 rows=228 loops=1)
>
> Any suggestions?
>
> SELECT z.atextfield,
> z.btextfield,
> z.abigintfield,
> p.achar255field, p.ptextfield,
> z.achar1field, u.aboolfield,
> z.textfield1,
> z.achar8field,
> z.achar16field
> FROM tablea ru
> INNER JOIN tableb u ON ( u.atextfield = ru.anothertextfield )
> INNER JOIN tablec z ON u.atextfield = z.atextfield
> INNER JOIN tabled p ON p.id = z.pid
> LEFT JOIN tablee m ON u.atextfield = m.atextfield AND m.boolcol5
> WHERE ru.atextfield = 'thelookupval'
> AND u.boolcol1 IS TRUE
> AND u.boolcol2 IS FALSE
> AND ru.achar1field <> 'N'
> AND ru.boolcol3 IS FALSE
> AND NOT EXISTS ( SELECT 'x' FROM tablea fru WHERE fru.atextfield =
> ru.anothertextfield AND fru.boolcol3 IS TRUE )
> AND EXISTS ( SELECT 'x' FROM tablef s WHERE s.atextfield = ru.atextfield
> AND s.boolcol4 IS TRUE )
> ORDER by ru.anothertextfield asc
>
>
>
> Sort (cost=2341.96..2341.97 rows=2 width=146) (actual
> time=1118.810..1119.098 rows=228 loops=1)
> Sort Key: ru.anothertextfield
> -> Nested Loop Left Join (cost=0.00..2341.95 rows=2 width=146) (actual
> time= 0.930..1117.258 rows=228 loops=1)
> -> Nested Loop (cost=0.00..2313.36 rows=2 width=131) (actual
> time=0.842..914.554 rows=228 loops=1)
> -> Nested Loop (cost=0.00..2296.65 rows=2 width=93) (actual
> time= 0.765..901.916 rows=228 loops=1)
> -> Nested Loop (cost=0.00..2281.98 rows=2 width=72)
> (actual time=0.690..893.648 rows=228 loops=1)
> -> Index Scan using i_tablea_atextfield on tablea
> ru (cost= 0.00..2265.28 rows=2 width=12) (actual time=0.624..881.313
> rows=228 loops=1)
> Index Cond: (atextfield =
> 'thelookupval'::text)
> Filter: ((achar1field <> 'N'::bpchar) AND
> (boolcol3 IS FALSE) AND (NOT (subplan)) AND (subplan))
> SubPlan
> -> Index Scan using tablef_pkey on tablef
> s (cost=0.00..8.34 rows=1 width=0) (actual time=0.016..0.016 rows=1
> loops=228)
> Index Cond: (atextfield = $1)
> Filter: (boolcol4 IS TRUE)
> -> Bitmap Heap Scan on tablea fru
> (cost=4.61..90.41 rows=1 width=0) (actual time=3.590..3.590 rows=0
> loops=243)
> Recheck Cond: (atextfield = $0)
> Filter: (boolcol3 IS TRUE)
> -> Bitmap Index Scan on
> i_tablea_atextfield (cost= 0.00..4.61 rows=22 width=0) (actual
> time=0.044..0.044 rows=17 loops=243)
> Index Cond: (atextfield = $0)
> -> Index Scan using tablec_pkey on tablec z
> (cost= 0.00..8.34 rows=1 width=60) (actual time=0.047..0.049 rows=1
> loops=228)
> Index Cond: (z.atextfield =
> ru.anothertextfield)
> -> Index Scan using tabled_pkey on tabled p (cost=
> 0.00..7.32 rows=1 width=29) (actual time=0.030..0.031 rows=1 loops=228)
> Index Cond: (p.id = z.pid)
> -> Index Scan using tableb_pkey on tableb u (cost=
> 0.00..8.34 rows=1 width=38) (actual time=0.049..0.051 rows=1 loops=228)
> Index Cond: (u.atextfield = ru.anothertextfield)
> Filter: ((boolcol1 IS TRUE) AND (boolcol2" IS FALSE))"
> -> Index Scan using tablee_atextfield_idx on tablee m
> (cost=0.00..14.28 rows=1 width=39) (actual time=0.883..0.883 rows=0
> loops=228)
> Index Cond: (u.atextfield = m.atextfield)
>
>
>
>

I see a lot of Nested Nested Nested Loops on text fields which means a
lot of string comparisons.
Try using HashJoin here.

ANALYZE your database and explain again. Or try forcing a hashjoin if you still
dont see a difference.

--Imad

Hello

there is some differences:

ndex Scan using i_tablea_atextfield on tablea ru (cost= 0.00..2265.28
rows=2 width=12) (actual time=0.624..881.313 rows=228 loops=1)
Index Cond: (atextfield = 'thelookupval'::text)
Filter: ((achar1field <> 'N'::bpchar)
AND (boolcol3 IS FALSE) AND (NOT (subplan)) AND (subplan))

try tu increase statistic for column atextfield on table ru, ANALYZE
it again and test it.

Pavel

On 24/12/2007, imad <immaad(at)gmail(dot)com> wrote:
> On Dec 24, 2007 7:46 PM, Marc <pgsql-general(at)mbreslow(dot)net> wrote:
> > Hey Folks,
> >
> > This query is running really slowly. Sometimes much slower then others. I
> > have a feeling that there may be contention on one of the indices it is
> > using. In the explain plan, it looks like it estimates 2 rows but actually
> > finds 228 rows? Is that really bad?
> >
>
> You should do an ANALYZE if actual rows are significantly different.
> And they are.
>
> >
> >
> > Query and explain plan are below. Seems like it spend the most time doing
> > Index Scan using i_tablea_atextfield on tablea ru (cost=0.00..2265.28
> > rows=2 width=12) (actual time=0.624..881.313 rows=228 loops=1)
> >
> > Any suggestions?
> >
> > SELECT z.atextfield,
> > z.btextfield,
> > z.abigintfield,
> > p.achar255field, p.ptextfield,
> > z.achar1field, u.aboolfield,
> > z.textfield1,
> > z.achar8field,
> > z.achar16field
> > FROM tablea ru
> > INNER JOIN tableb u ON ( u.atextfield = ru.anothertextfield )
> > INNER JOIN tablec z ON u.atextfield = z.atextfield
> > INNER JOIN tabled p ON p.id = z.pid
> > LEFT JOIN tablee m ON u.atextfield = m.atextfield AND m.boolcol5
> > WHERE ru.atextfield = 'thelookupval'
> > AND u.boolcol1 IS TRUE
> > AND u.boolcol2 IS FALSE
> > AND ru.achar1field <> 'N'
> > AND ru.boolcol3 IS FALSE
> > AND NOT EXISTS ( SELECT 'x' FROM tablea fru WHERE fru.atextfield =
> > ru.anothertextfield AND fru.boolcol3 IS TRUE )
> > AND EXISTS ( SELECT 'x' FROM tablef s WHERE s.atextfield = ru.atextfield
> > AND s.boolcol4 IS TRUE )
> > ORDER by ru.anothertextfield asc
> >
> >
> >
> > Sort (cost=2341.96..2341.97 rows=2 width=146) (actual
> > time=1118.810..1119.098 rows=228 loops=1)
> > Sort Key: ru.anothertextfield
> > -> Nested Loop Left Join (cost=0.00..2341.95 rows=2 width=146) (actual
> > time= 0.930..1117.258 rows=228 loops=1)
> > -> Nested Loop (cost=0.00..2313.36 rows=2 width=131) (actual
> > time=0.842..914.554 rows=228 loops=1)
> > -> Nested Loop (cost=0.00..2296.65 rows=2 width=93) (actual
> > time= 0.765..901.916 rows=228 loops=1)
> > -> Nested Loop (cost=0.00..2281.98 rows=2 width=72)
> > (actual time=0.690..893.648 rows=228 loops=1)
> > -> Index Scan using i_tablea_atextfield on tablea
> > ru (cost= 0.00..2265.28 rows=2 width=12) (actual time=0.624..881.313
> > rows=228 loops=1)
> > Index Cond: (atextfield =
> > 'thelookupval'::text)
> > Filter: ((achar1field <> 'N'::bpchar) AND
> > (boolcol3 IS FALSE) AND (NOT (subplan)) AND (subplan))
> > SubPlan
> > -> Index Scan using tablef_pkey on tablef
> > s (cost=0.00..8.34 rows=1 width=0) (actual time=0.016..0.016 rows=1
> > loops=228)
> > Index Cond: (atextfield = $1)
> > Filter: (boolcol4 IS TRUE)
> > -> Bitmap Heap Scan on tablea fru
> > (cost=4.61..90.41 rows=1 width=0) (actual time=3.590..3.590 rows=0
> > loops=243)
> > Recheck Cond: (atextfield = $0)
> > Filter: (boolcol3 IS TRUE)
> > -> Bitmap Index Scan on
> > i_tablea_atextfield (cost= 0.00..4.61 rows=22 width=0) (actual
> > time=0.044..0.044 rows=17 loops=243)
> > Index Cond: (atextfield = $0)
> > -> Index Scan using tablec_pkey on tablec z
> > (cost= 0.00..8.34 rows=1 width=60) (actual time=0.047..0.049 rows=1
> > loops=228)
> > Index Cond: (z.atextfield =
> > ru.anothertextfield)
> > -> Index Scan using tabled_pkey on tabled p (cost=
> > 0.00..7.32 rows=1 width=29) (actual time=0.030..0.031 rows=1 loops=228)
> > Index Cond: (p.id = z.pid)
> > -> Index Scan using tableb_pkey on tableb u (cost=
> > 0.00..8.34 rows=1 width=38) (actual time=0.049..0.051 rows=1 loops=228)
> > Index Cond: (u.atextfield = ru.anothertextfield)
> > Filter: ((boolcol1 IS TRUE) AND (boolcol2" IS FALSE))"
> > -> Index Scan using tablee_atextfield_idx on tablee m
> > (cost=0.00..14.28 rows=1 width=39) (actual time=0.883..0.883 rows=0
> > loops=228)
> > Index Cond: (u.atextfield = m.atextfield)
> >
> >
> >
> >
>
>
> I see a lot of Nested Nested Nested Loops on text fields which means a
> lot of string comparisons.
> Try using HashJoin here.
>
> ANALYZE your database and explain again. Or try forcing a hashjoin if you still
> dont see a difference.
>
>
> --Imad
>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faq
>