Re: Re: 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?

If you guys succeed in making this class of query perform, you'll have
beat out the professional consulting firm we hired, which was all but
useless! The query is usually slow, but particular combinations of
words seem to make it obscenely slow.

The query plans are now attached (sorry I did not start there: many
lists reject attachments). Or you can click on "text" at the query
planner analysis site http://explain.depesz.com/s/qYq

_Here's typical server load:_
Tasks: 166 total, 1 running, 165 sleeping, 0 stopped, 0 zombie
Cpu(s): 1.2%us, 0.9%sy, 0.0%ni, 86.5%id, 11.2%wa, 0.0%hi, 0.1%si,
0.0%st
Mem: 32966936k total, 32873860k used, 93076k free, 2080k buffers
Swap: 33554424k total, 472k used, 33553952k free, 30572904k cached

_
Configurations modified from Postgres 8.3 default are:_
listen_addresses = '10.100.2.11, 10.101.2.11' # what IP address(es) to
listen on;
port = 5432 # (change requires restart)
max_connections = 400 # (change requires restart)
shared_buffers = 4096MB # min 128kB or max_connections*16kB
work_mem = 16MB # min 64kB
max_fsm_pages = 500000 # default:20000
min:max_fsm_relations*16,6 bytes see:MAIN-5740
max_fsm_relations = 2700 # min 100, ~70 bytes each
checkpoint_segments = 20 # in logfile segments, min 1,
16MB each
random_page_cost = 2.0 # same scale as above
effective_cache_size = 28672MB
default_statistics_target = 150 # range 1-1000
log_destination = 'syslog' # Valid values are combinations of
log_min_error_statement = error # values in order of decreasing detail:
log_min_duration_statement = 5000 # -1 is disabled, 0 logs all
statements
log_checkpoints = on # default off
autovacuum_naptime = 5min # time between autovacuum runs
escape_string_warning = off # default:on (See bepress
MAIN-4857)
standard_conforming_strings = off # deafult:off (See bepress
MAIN-4857)

production=# EXPLAIN ANALYZE SELECT context_key FROM article_words
JOIN words using (word_key) WHERE word = 'insider';
-------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.00..23393.15 rows=23 width=4) (actual
time=0.077..15.637 rows=4003 loops=1)
-> Index Scan using words_word on words (cost=0.00..5.47 rows=1
width=4) (actual time=0.049..0.051 rows=1 loops=1)
Index Cond: ((word)::text = 'insider'::text)
-> Index Scan using article_words_wc on article_words
(cost=0.00..23234.38 rows=12264 width=8) (actual time=0.020..7.237
rows=4003 loops=1)
Index Cond: (article_words.word_key = words.word_key)
Total runtime: 19.776 ms

production=# EXPLAIN ANALYZE SELECT context_key FROM article_words
WHERE word_key = 3675;
-------------------------------------------------------------------------------------------------------------------------------------------
Index Scan using article_words_wc on article_words
(cost=0.00..21433.53 rows=11309 width=4) (actual time=0.025..7.579
rows=4003 loops=1)
Index Cond: (word_key = 3675)
Total runtime: 11.704 ms

production=# explain analyze select count(*) from article_words;
Aggregate (cost=263831.63..263831.64 rows=1 width=0) (actual
time=35851.654..35851.655 rows=1 loops=1)
-> Seq Scan on words (cost=0.00..229311.30 rows=13808130 width=0)
(actual time=0.043..21281.124 rows=13808184 loops=1)
Total runtime: 35851.723 ms

production=# select count(*) from words;
13,808,184

production=# explain analyze select count(*) from article_words;
Aggregate (cost=5453242.40..5453242.41 rows=1 width=0) (actual
time=776504.017..776504.018 rows=1 loops=1)
-> Seq Scan on article_words (cost=0.00..4653453.52 rows=319915552
width=0) (actual time=0.034..438969.347 rows=319956663 loops=1)
Total runtime: 776504.177 ms

production=# select count(*) from article_words;
319,956,720