Re: Forcing the right queryplan

On Tue, Sep 07, 2010 at 07:26:25PM +0200, Alban Hertroys wrote:
>
> Do you have output of explain analyse for these queries as well? It's
> hard to see what is actually going on with just the explain - we can't
> see which part of the query is more expensive than the planner
> expected, for starters.

Hi Alban,

Here are the explain analyse versions:

syslog=# explain analyze SELECT id, devicereportedtime, facility, priority, fromhost, syslogtag, infounitid, message FROM systemevents WHERE ( (to_tsvector('english', message) @@ to_tsquery ( '131.211.112.9')) ) ORDER BY id DESC LIMIT 100;
Q
UERY PLAN

--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
--------
Limit (cost=0.00..1205.09 rows=100 width=158) (actual time=16740.139..2360334.
006 rows=100 loops=1)
-> Index Scan Backward using systemevents_pkey on systemevents (cost=0.00..
2888974.17 rows=239730 width=158) (actual time=16740.137..2360333.916 rows=100 l
oops=1)
Filter: (to_tsvector('english'::regconfig, message) @@ to_tsquery('131.
211.112.9'::text))
Total runtime: 2360334.078 ms
(4 rows)

syslog=# explain analyze SELECT id, devicereportedtime, facility, priority, fromhost, syslogtag, infounitid, message FROM systemevents WHERE ( ( to_tsvector('english', message) @@ to_tsquery ( '131.211.112.9')) ) ORDER BY id DESC LIMIT 500000;
QUERY PLAN

--------------------------------------------------------------------------------
---------------------------------------------------------------
Limit (cost=727944.30..728543.82 rows=239805 width=158) (actual time=1805.251.
.1805.388 rows=464 loops=1)
-> Sort (cost=727944.30..728543.82 rows=239805 width=158) (actual time=1805
.249..1805.300 rows=464 loops=1)
Sort Key: id
Sort Method: quicksort Memory: 148kB
-> Bitmap Heap Scan on systemevents (cost=61221.23..668806.93 rows=23
9805 width=158) (actual time=9.131..1786.406 rows=464 loops=1)
Recheck Cond: (to_tsvector('english'::regconfig, message) @@ to_t
squery('131.211.112.9'::text))
-> Bitmap Index Scan on msgs_idx (cost=0.00..61161.28 rows=2398
05 width=0) (actual time=0.790..0.790 rows=464 loops=1)
Index Cond: (to_tsvector('english'::regconfig, message) @@
to_tsquery('131.211.112.9'::text))
Total runtime: 1805.483 ms
(9 rows)

> Odd that more records and a more complicated plan gives faster results...
> That's why I think we'd really want to see explain analyse output.
> I'm guessing that there are a lot of records matching your search string

As you can see, there are only 464 matches.

> One thing I do notice is that the first plan uses the index on id
> instead of the ts_vector one. For queries like those you could try to
> use a combined index like this:
>
> CREATE INDEX msgs_idx (to_tsvector('english'::regconfig, message), id)
> ON systemevents USING (gin);

I will look into this.

Thanks,
--
Henk van Lingen, ICT-SC Netwerk & Telefonie, (o- -+
Universiteit Utrecht, Jenalaan 18a, room 0.12 /\ |
phone: +31-30-2538453 v_/_ |
http://henk.vanlingen.net/ http://www.tuxtown.net/netiquette/