Обсуждение: 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');




 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

> 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

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

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>

> 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