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
FROMsystemevents 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
FROMsystemevents 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/