Interpreting EXPLAIN ANALYSE

Started by Henry C.almost 15 years ago5 messagesgeneral
Jump to latest
#1Henry C.
henka@cityweb.co.za

Greets,

I'm trying to figure out why the following SELECT has become slow (hardware,
code changes, etc) and would appreciate any comments on interpreting the
EXPLAIN ANALYZE output. It *used* to take a few seconds at most, but not
anymore... In figuring out which part is taking so long, what's the important
bit to examine (besides making sure indexes are being used)? Presumably
"actual time="?

If I can identify which index is taking the longest from the output below,
then I can look at moving it to a faster TABLESPACE or something.

explain analyze
SELECT pl.sss, pl.did, pl.lid, pr.rank, plc.obl
FROM plink pl LEFT JOIN prank pr USING (did)
LEFT JOIN plink_count plc ON md5(plc.did)=md5(pr.did)
LEFT JOIN snames s ON s.name=pl.sss
WHERE
s.bsit=0 AND s.disabled=0 AND
s.prankignore=0 AND
pl.lid = lower(E'stuff');

Nested Loop Left Join (cost=22717.85..40240.86 rows=47 width=177) (actual
time=532299.546..532385.533 rows=1 loops=1)
-> Nested Loop Left Join (cost=22717.84..40055.65 rows=47 width=205)
(actual time=532299.546..532385.533 rows=1 loops=1)
-> Hash Join (cost=22717.84..39936.36 rows=47 width=141) (actual
time=532297.546..532383.533 rows=1 loops=1)
Hash Cond: (pl.sss = s.name)
-> Index Scan using sk_plink3 on plink pl
(cost=0.00..17155.35 rows=16718 width=141) (actual
time=0.000..0.000 rows=1 loops=1)
Index Cond: (lid = 'stuff'::text)
-> Hash (cost=22717.57..22717.57 rows=22 width=32) (actual
time=461886.321..461886.321 rows=164147851 loops=1)
Buckets: 1024 Batches: 8 (originally 1) Memory Usage:
1548289kB
-> Bitmap Heap Scan on snames s
(cost=18260.53..22717.57 rows=22 width=32) (actual
time=45939.971..351687.125 rows=164147851 loops=1)
Recheck Cond: ((bsit = 0) AND (prankignore = 0))
Filter: (disabled = 0)
-> BitmapAnd (cost=18260.53..18260.53 rows=4455
width=0) (actual time=43802.298..43802.298 rows=0
loops=1)
-> Bitmap Index Scan on snames7
(cost=0.00..9130.13 rows=890933 width=0)
(actual time=20285.896..20285.896
rows=178144776 loops=1)
Index Cond: (bsit = 0)
-> Bitmap Index Scan on sk_snames20
(cost=0.00..9130.13 rows=890933 width=0)
(actual time=22245.596..22245.596
rows=178186036 loops=1)
Index Cond: (prankignore = 0)
-> Index Scan using sk_prank on prank pr (cost=0.00..2.53 rows=1
width=64) (actual time=2.000..2.000 rows=0 loops=1)
Index Cond: (pl.did = pr.did)
-> Index Scan using skplink_count0 on plink_count plc (cost=0.00..3.92
rows=1 width=36) (actual time=0.000..0.000 rows=0 loops=1)
Index Cond: (md5(plc.did) = md5(pr.did))
Total runtime: 532386.533 ms

Thanks
Henry

#2Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Henry C. (#1)
Re: Interpreting EXPLAIN ANALYSE

Greets,

I'm trying to figure out why the following SELECT has become slow
(hardware,
code changes, etc) and would appreciate any comments on interpreting the
EXPLAIN ANALYZE output. It *used* to take a few seconds at most, but not
anymore... In figuring out which part is taking so long, what's the
important
bit to examine (besides making sure indexes are being used)? Presumably
"actual time="?

If I can identify which index is taking the longest from the output below,
then I can look at moving it to a faster TABLESPACE or something.

explain analyze
SELECT pl.sss, pl.did, pl.lid, pr.rank, plc.obl
FROM plink pl LEFT JOIN prank pr USING (did)
LEFT JOIN plink_count plc ON md5(plc.did)=md5(pr.did)
LEFT JOIN snames s ON s.name=pl.sss
WHERE
s.bsit=0 AND s.disabled=0 AND
s.prankignore=0 AND
pl.lid = lower(E'stuff');

See this http://explain.depesz.com/s/THh

There's something very wrong with snames - the planner expects 22 rows but
gets 164147851. Which probably causes a bad plan choice or something like
that. Try to analyze the snames table (and maybe increase the statistics
target on the columns).

regards
Tomas

#3Henry C.
henka@cityweb.co.za
In reply to: Tomas Vondra (#2)
Re: Interpreting EXPLAIN ANALYSE

On Fri, June 3, 2011 13:57, tv@fuzzy.cz wrote:

See this http://explain.depesz.com/s/THh

There's something very wrong with snames - the planner expects 22 rows but
gets 164147851. Which probably causes a bad plan choice or something like that.
Try to analyze the snames table (and maybe increase the statistics
target on the columns).

Thanks - like you say, looks like the interesting bit is:

rows=22 --> rows=164147851 for table snames.

Nice online tool you have there my china!

Cheers
Henry

#4Henry C.
henka@cityweb.co.za
In reply to: Tomas Vondra (#2)
Re: Interpreting EXPLAIN ANALYSE

On Fri, June 3, 2011 13:57, tv@fuzzy.cz wrote:

There's something very wrong with snames - the planner expects 22 rows but
gets 164147851. Which probably causes a bad plan choice or something like that.
Try to analyze the snames table (and maybe increase the statistics
target on the columns).

ANALYZE is your friend indeed, like a nice cold beer... from over 500k ms to
1 ms.

I was running ANALYZE on one of the tables in the join, but not the others...
<sigh>

#5Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Henry C. (#4)
Re: Interpreting EXPLAIN ANALYSE

On Fri, June 3, 2011 13:57, tv@fuzzy.cz wrote:

There's something very wrong with snames - the planner expects 22 rows
but
gets 164147851. Which probably causes a bad plan choice or something
like that.
Try to analyze the snames table (and maybe increase the statistics
target on the columns).

ANALYZE is your friend indeed, like a nice cold beer... from over 500k ms
to
1 ms.

I was running ANALYZE on one of the tables in the join, but not the
others...
<sigh>

So you have turned off autovacuum (that should handle this automatically)
or you're running an old version (autovacuum was enabled by default in 8.3
IIRC).

regards
Tomas