Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
On Sat, Feb 13, 2010 at 2:58 AM, Bryce Nesbitt bry...@obviously.com wrote: So as the op, back to the original posting In the real world, what should I do? Does it make sense to pull the AND articles.indexed clause into an outer query? Will that query simply perform poorly on other arbitrary combinations of words? It's really hard to say whether a query that performs better is going to always perform better on every combination of words. My suggestion is - try it and see. It's my experience that rewriting queries is a pretty effective way of speeding them up, but I can't vouch for what will happen in your particular case. It's depressing to see that increasing the statistics target didn't help much; but that makes me think that the problem is that your join selectivity estimates are off, as Tom and Jorge said upthread. Rewriting the query or trying an upgrade are probably your only options. ...Robert -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Bryce Nesbitt bry...@obviously.com wrote: I've got a very slow query, which I can make faster by doing something seemingly trivial. Out of curiosity, what kind of performance do you get with?: EXPLAIN ANALYZE SELECT contexts.context_key FROM contexts JOIN articles ON (articles.context_key = contexts.context_key) JOIN matview_82034 ON (matview_82034.context_key = contexts.context_key) WHERE EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'insider' ) AND EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'trading' ) AND EXISTS ( SELECT * FROM virtual_ancestors a JOIN bp_categories ON (bp_categories.context_key = a.ancestor_key) WHERE a.context_key = contexts.context_key AND lower(bp_categories.category) = 'law' ) AND articles.indexed ; (You may have to add some table aliases in the subqueries.) If you are able to make a copy on 8.4 and test the various forms, that would also be interesting. I suspect that the above might do pretty well in 8.4. -Kevin -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Exists can be quite slow. So can not exists See if you can re-write it using a sub-select - just replace the exists with (select ...) is not null Surprisingly this often results in a MUCH better query plan under Postgresql. Why the planner evaluates it better eludes me (it shouldn't) but the differences are often STRIKING - I've seen factor-of-10 differences in execution performance. Kevin Grittner wrote: Bryce Nesbitt bry...@obviously.com wrote: I've got a very slow query, which I can make faster by doing something seemingly trivial. Out of curiosity, what kind of performance do you get with?: EXPLAIN ANALYZE SELECT contexts.context_key FROM contexts JOIN articles ON (articles.context_key = contexts.context_key) JOIN matview_82034 ON (matview_82034.context_key = contexts.context_key) WHERE EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'insider' ) AND EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'trading' ) AND EXISTS ( SELECT * FROM virtual_ancestors a JOIN bp_categories ON (bp_categories.context_key = a.ancestor_key) WHERE a.context_key = contexts.context_key AND lower(bp_categories.category) = 'law' ) AND articles.indexed ; (You may have to add some table aliases in the subqueries.) If you are able to make a copy on 8.4 and test the various forms, that would also be interesting. I suspect that the above might do pretty well in 8.4. -Kevin attachment: karl.vcf -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Karl Denninger k...@denninger.net wrote: Kevin Grittner wrote: I suspect that the above might do pretty well in 8.4. Exists can be quite slow. So can not exists See if you can re-write it using a sub-select - just replace the exists with (select ...) is not null Surprisingly this often results in a MUCH better query plan under Postgresql. Why the planner evaluates it better eludes me (it shouldn't) but the differences are often STRIKING - I've seen factor-of-10 differences in execution performance. Have you seen such a difference under 8.4? Can you provide a self-contained example? -Kevin -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Yes: select forum, * from post where marked is not true and toppost = 1 and (select login from ignore_thread where login='xxx' and number=post.number) is null and (replied now() - '30 days'::interval) and (replied (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false and (replied (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null) order by pinned desc, replied desc offset 0 limit 100 Returns the following query plan: QUERY PLAN - Limit (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=771.000..771.455 rows=100 loops=1) - Sort (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=770.996..771.141 rows=100 loops=1) Sort Key: post.pinned, post.replied Sort Method: top-N heapsort Memory: 120kB - Index Scan using post_top on post (cost=0.00..5301575.62 rows=1 width=433) (actual time=0.664..752.994 rows=3905 loops=1) Index Cond: (toppost = 1) Filter: ((marked IS NOT TRUE) AND (replied (now() - '30 days'::interval)) AND ((SubPlan 1) IS NULL) AND ((replied (SubPlan 2)) IS NOT FALSE) AND ((replied (SubPlan 3)) IS NOT FALSE) AND ((forum = (SubPlan 4)) OR ((SubPlan 5) IS NULL))) SubPlan 1 - Seq Scan on ignore_thread (cost=0.00..5.45 rows=1 width=7) (actual time=0.037..0.037 rows=0 loops=3905) Filter: ((login = 'xxx'::text) AND (number = $0)) SubPlan 2 - Index Scan using forumlog_composite on forumlog (cost=0.00..9.50 rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=3905) Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number IS NULL)) SubPlan 3 - Index Scan using forumlog_composite on forumlog (cost=0.00..9.50 rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=3905) Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number = $0)) SubPlan 4 - Index Scan using excludenew_pkey on excludenew (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905) Index Cond: ((who = 'xxx'::text) AND (forum_name = $1)) SubPlan 5 - Index Scan using excludenew_pkey on excludenew (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905) Index Cond: ((who = 'xxx'::text) AND (forum_name = $1)) Total runtime: 771.907 ms (23 rows) The alternative: select forum, * from post where marked is not true and toppost = 1 and not exists (select login from ignore_thread where login='xxx' and number=post.number) and (replied now() - '30 days'::interval) and (replied (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false and (replied (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null) order by pinned desc, replied desc offset 0 limit 100 goes nuts. (Yes, I know, most of those others which are not false could be Exists too) Explain Analyze on the alternative CLAIMS the same query planner time (within a few milliseconds) with explain analyze. But if I replace the executing code with one that has the alternative (not exists) syntax in it, the system load goes to crap instantly and the execution times in the wild go bananas. I don't know why it does - I just know THAT it does. When I first added that top clause in there (to allow people an individual ignore thread list) the system load went bananas immediately and forced me to back it out. When I re-wrote the query as above the performance was (and remains) fine. I'm running 8.4.2. I agree (in advance) it shouldn't trash performance - all I know is that it does and forced me to re-write the query. Kevin Grittner wrote: Karl Denninger k...@denninger.net wrote: Kevin Grittner wrote: I suspect that the above might do pretty well in 8.4. Exists can be quite slow. So can not exists
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Karl Denninger k...@denninger.net wrote: Kevin Grittner wrote: Have you seen such a difference under 8.4? Can you provide a self-contained example? Yes: [query and EXPLAIN ANALYZE of fast query] The alternative: [query with no other information] goes nuts. Which means what? Could you post an EXPLAIN ANALYZE, or at least an EXPLAIN, of the slow version? Can you post the table structure, including indexes? -Kevin -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Karl Denninger k...@denninger.net writes: Explain Analyze on the alternative CLAIMS the same query planner time (within a few milliseconds) with explain analyze. But if I replace the executing code with one that has the alternative (not exists) syntax in it, the system load goes to crap instantly and the execution times in the wild go bananas. Could we see the actual explain analyze output, and not some handwaving? What I would expect 8.4 to do with the NOT EXISTS version is to convert it to an antijoin --- probably a hash antijoin given that the subtable is apparently small. That should be a significant win compared to repeated seqscans as you have now. The only way I could see for it to be a loss is that that join would probably be performed after the other subplan tests instead of before. However, the rowcounts for your original query suggest that all the subplans get executed the same number of times; so at least on the test values you used here, all those conditions succeed. Maybe your test values were not representative of in the wild cases, and in the real usage it's important to make this test before the others. If that's what it is, you might see what happens when all of the sub-selects are converted to exists/not exists style, instead of having a mishmash... regards, tom lane -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
Kevin Grittner wrote: Bryce Nesbitt bry...@obviously.com wrote: I've got a very slow query, which I can make faster by doing something seemingly trivial. Out of curiosity, what kind of performance do you get with?: EXPLAIN ANALYZE SELECT contexts.context_key FROM contexts JOIN articles ON (articles.context_key = contexts.context_key) JOIN matview_82034 ON (matview_82034.context_key = contexts.context_key) WHERE EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'insider' ) AND EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'trading' ) AND EXISTS ( SELECT * FROM virtual_ancestors a JOIN bp_categories ON (bp_categories.context_key = a.ancestor_key) WHERE a.context_key = contexts.context_key AND lower(bp_categories.category) = 'law' ) AND articles.indexed ; 512,600ms query becomes 225,976ms. Twice as fast on pos Definitely not beating the 7500ms version. PostgreSQL 8.3.4 EXPLAIN ANALYZE SELECT contexts.context_key FROM contexts JOIN articles ON (articles.context_key = contexts.context_key) JOIN matview_82034 ON (matview_82034.context_key = contexts.context_key) WHERE EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'insider' ) AND EXISTS ( SELECT * FROM article_words JOIN words using (word_key) WHERE context_key = contexts.context_key AND word = 'trading' ) AND EXISTS ( SELECT * FROM virtual_ancestors a JOIN bp_categories ON (bp_categories.context_key = a.ancestor_key) WHERE a.context_key = contexts.context_key AND lower(bp_categories.category) = 'law' ) AND articles.indexed ; Nested Loop (cost=13511.95..13662023.05 rows=19282 width=4) (actual time=3070.834..225973.159 rows=622 loops=1) - Hash Join (cost=13511.95..356938.38 rows=177937 width=8) (actual time=1106.242..7520.756 rows=351337 loops=1) Hash Cond: (articles.context_key = matview_82034.context_key) - Seq Scan on articles (cost=0.00..334502.90 rows=386266 width=4) (actual time=0.030..4031.203 rows=355626 loops=1) Filter: indexed - Hash (cost=6322.20..6322.20 rows=438220 width=4) (actual time=1105.663..1105.663 rows=438220 loops=1) - Seq Scan on matview_82034 (cost=0.00..6322.20 rows=438220 width=4) (actual time=7.105..544.072 rows=438220 loops=1) - Index Scan using contexts_pkey on contexts (cost=0.00..74.76 rows=1 width=4) (actual time=0.619..0.619 rows=0 loops=351337) Index Cond: (contexts.context_key = articles.context_key) Filter: ((subplan) AND (subplan) AND (subplan)) SubPlan - Nested Loop (cost=0.00..30.54 rows=1 width=17) (actual time=6.119..6.119 rows=1 loops=983) - Index Scan using words_word on words (cost=0.00..5.50 rows=1 width=13) (actual time=0.028..0.029 rows=1 loops=983) Index Cond: ((word)::text = 'trading'::text) - Index Scan using article_words_cw on article_words (cost=0.00..25.02 rows=1 width=8) (actual time=6.082..6.082 rows=1 loops=983) Index Cond: ((public.article_words.context_key = $0) AND (public.article_words.word_key = public.words.word_key)) - Nested Loop (cost=0.00..30.54 rows=1 width=17) (actual time=6.196..6.196 rows=0 loops=26494) - Index Scan using words_word on words (cost=0.00..5.50 rows=1 width=13) (actual time=0.022..0.024 rows=1 loops=26494) Index Cond: ((word)::text = 'insider'::text) - Index Scan using article_words_cw on article_words (cost=0.00..25.02 rows=1 width=8) (actual time=6.165..6.165 rows=0 loops=26494) Index Cond: ((public.article_words.context_key = $0) AND (public.article_words.word_key = public.words.word_key)) - Nested Loop (cost=0.00..38.38 rows=3 width=29) (actual time=0.122..0.122 rows=0 loops=351337) - Index Scan using virtual_context_key_idx on virtual_ancestors a (cost=0.00..7.35 rows=5 width=10) (actual time=0.074..0.085 rows=5
Re: [PERFORM] 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk?
So as the op, back to the original posting In the real world, what should I do? Does it make sense to pull the "AND articles.indexed" clause into an outer query? Will that query simply perform poorly on other arbitrary combinations of words? I'm happy to test any given query against the same set of servers. If it involves a persistent change it has to run on a test server). For example, the Robert Haas method: # ... Total runtime: 254207.857 ms # ALTER TABLE article_words ALTER COLUMN word_key SET STATISTICS 1000; # ANALYZE VERBOSE article_words INFO: analyzing "public.article_words" INFO: "article_words": scanned 30 of 1342374 pages, containing 64534899 live rows and 3264839 dead rows; 30 rows in sample, 288766568 estimated total rows ANALYZE # ... Total runtime: 200591.751 ms # ALTER TABLE article_words ALTER COLUMN word_key SET STATISTICS 50; # ANALYZE VERBOSE article_words # ... Total runtime: 201204.972 ms Sadly, it made essentially zero difference. Attached. preproduction-20091214=# EXPLAIN ANALYZE SELECT contexts.context_key FROM contexts JOIN articles ON (articles.context_key=contexts.context_key) JOIN matview_82034 ON (contexts.context_key=matview_82034.context_key) WHERE contexts.context_key IN (SELECT context_key FROM article_words JOIN words using (word_key) WHERE word = 'insider' INTERSECT SELECT context_key FROM article_words JOIN words using (word_key) WHERE word = 'trading') AND contexts.context_key IN (SELECT a.context_key FROM virtual_ancestors a JOIN bp_categories ON (a.ancestor_key = bp_categories.context_key) WHERE lower(bp_categories.category) = 'law') AND articles.indexed; QUERY PLAN --- Nested Loop (cost=12861.91..62150.21 rows=2 width=4) (actual time=136.789..200744.455 rows=546 loops=1) - Nested Loop IN Join (cost=12861.91..62148.32 rows=1 width=16) (actual time=136.777..200737.004 rows=546 loops=1) Join Filter: (a.context_key = articles.context_key) - Nested Loop (cost=12861.91..12875.48 rows=2 width=12) (actual time=55.674..116.443 rows=1306 loops=1) - Nested Loop (cost=12861.91..12871.68 rows=2 width=8) (actual time=55.662..97.863 rows=1306 loops=1) - Subquery Scan IN_subquery (cost=12861.91..12862.18 rows=5 width=4) (actual time=55.639..75.777 rows=1473 loops=1) - SetOp Intersect (cost=12861.91..12862.14 rows=5 width=4) (actual time=55.638..73.724 rows=1473 loops=1) - Sort (cost=12861.91..12862.02 rows=46 width=4) (actual time=55.631..62.140 rows=17892 loops=1) Sort Key: *SELECT* 1.context_key Sort Method: quicksort Memory: 1607kB - Append (cost=0.00..12860.63 rows=46 width=4) (actual time=0.040..42.026 rows=17892 loops=1) - Subquery Scan *SELECT* 1 (cost=0.00..6430.32 rows=23 width=4) (actual time=0.039..6.909 rows=3583 loops=1) - Nested Loop (cost=0.00..6430.09 rows=23 width=4) (actual time=0.038..5.110 rows=3583 loops=1) - Index Scan using words_word on words (cost=0.00..2.22 rows=1 width=4) (actual time=0.019..0.020 rows=1 loops=1) Index Cond: ((word)::text = 'insider'::text) - Index Scan using article_words_wc on article_words (cost=0.00..6323.81 rows=8325 width=8) (actual time=0.015..3.243 rows=3583 loops=1) Index Cond: (public.article_words.word_key = public.words.word_key) - Subquery Scan *SELECT* 2 (cost=0.00..6430.32 rows=23 width=4) (actual time=0.036..27.166 rows=14309 loops=1) - Nested Loop (cost=0.00..6430.09 rows=23 width=4) (actual time=0.035..20.037 rows=14309 loops=1) - Index Scan using words_word on words (cost=0.00..2.22 rows=1 width=4) (actual time=0.014..0.015 rows=1 loops=1) Index Cond: ((word)::text = 'trading'::text) - Index Scan using article_words_wc on article_words (cost=0.00..6323.81 rows=8325 width=8) (actual time=0.017..12.618 rows=14309
