Thread
-
The standard 'why does it take so long' question
Nigel J. Andrews <nandrews@investsystems.co.uk> — 2002-08-09T02:49:00Z
I have this query which used to yield this EXPLAIN ANALYZE [reformated] output: Sort (cost=12830.25..12830.25 rows=391 width=26) (actual time=39966.50..40305.70 rows=26982 loops=1) -> Nested Loop (cost=0.00..12813.40 rows=391 width=26) (actual time=69.16..34152.78 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx , chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=1.06..65.62 rows=2 loops=1) -> Index Scan using chat_post_usertime_idx on chat_post p (cost=0.00..6383.72 rows=1638 width=14) (actual time=72.31..10764.40 rows=13491 loops=2) Total runtime: 40739.10 msec where chat_post_usertime_idx is from: CREATE INDEX blah blah ... btree(user_id,time) After adding another index chat_post_time_user_idx, which reverses the order of the two columns in the above index, EXPLAIN ANALYZE yields: Sort (cost=9677.13..9677.13 rows=391 width=26) (actual time=62267.30..62554.49 rows=26982 loops=1) -> Nested Loop (cost=0.00..9660.28 rows=391 width=26) (actual time=174.77..55699.39 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx , chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=37.82..97.44 rows=2 loops=1) -> Index Scan using chat_post_timeuser_idx on chat_post p (cost=0.00..4806.89 rows=1638 width=14) (actual time=328.81..19932.71 rows=13491 loops=2) Total runtime: 62983.64 msec A 50% performance loss. I'm just trying to understand where the extra time comes from. Rearranging these explains into pairs of lines such that the first line of a pair is from the first explain and the second line from the second (works best in a _wide_ window) we can more easily compare things. Sort (cost=12830.25..12830.25 rows=391 width=26) (actual time=39966.50..40305.70 rows=26982 loops=1) Sort (cost=9677.13..9677.13 rows=391 width=26) (actual time=62267.30..62554.49 rows=26982 loops=1) -> Nested Loop (cost=0.00..12813.40 rows=391 width=26) (actual time=69.16..34152.78 rows=26982 loops=1) -> Nested Loop (cost=0.00..9660.28 rows=391 width=26) (actual time=174.77..55699.39 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx, chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=1.06..65.62 rows=2 loops=1) -> Index Scan using chat_user_lcasename_idx, chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=37.82..97.44 rows=2 loops=1) -> Index Scan using chat_post_usertime_idx on chat_post p (cost=0.00..6383.72 rows=1638 width=14) (actual time=72.31..10764.40 rows=13491 loops=2) -> Index Scan using chat_post_timeuser_idx on chat_post p (cost=0.00..4806.89 rows=1638 width=14) (actual time=328.81..19932.71 rows=13491 loops=2) Total runtime: 40739.10 msec Total runtime: 62983.64 msec It's pretty obvious from this that the index scan on chat_user takes longer when the new index is used on the other table. The index scan of the new index obviously takes longer as well. The first question is why would the index scan on chat_user take significantly longer than before? All I could think of is that the use of the new index has forced more disk reads. Does that sound reasonable and what are the alternatives? The next question is why would the index scan of the new index take significantly longer than before? From pg_class the new index uses 3814 pages and the preexisting one 4191. Therefore, one would have thought that the scan of the new index would take less time since less disk reads...uh oh, I think I may have just thought this out clearer...the new index takes longer to scan because it presumbly has to read more pages of the index to cover the required time interval than the older index because the older index has already narrowed the selection down by the user. Does that sound reasonable? That would then support my supposition about the first question, right? My ignorance will show once more now; why would the index scan on chat_user be impacted by a loss of index pages from shared memory/disk cache? Isn't this scan finished before the one on chat_post starts? Or would that scenario have meant a hash join would be in the explain output? This would go some way to explaining the extra time taken on chat_post if I'm missunderstanding this. I think I'll look up the explain output in the manual again as well. Oh, and before it's asked, the DB has been analyzed after the last data load and there was no change in data between these runs. Also: version ---------------------------------------------------------------------- PostgreSQL 7.2.1 on i386-unknown-freebsd3.3, compiled by GCC 2.7.2.3 I hope I haven't put y'all to sleep. -- Nigel J. Andrews Director --- Logictree Systems Limited Computer Consultants -
Re: The standard 'why does it take so long' question
Neil Conway <nconway@klamath.dyndns.org> — 2002-08-09T03:00:56Z
"Nigel J. Andrews" <nandrews@investsystems.co.uk> writes: > I have this query which used to yield this EXPLAIN ANALYZE > [reformated] output: Uh, *which* query, exactly? Cheers, Neil -- Neil Conway <neilconway@rogers.com> PGP Key ID: DB3C29FC
-
Re: The standard 'why does it take so long' question
Nigel J. Andrews <nandrews@investsystems.co.uk> — 2002-08-09T03:19:53Z
On 8 Aug 2002, Neil Conway wrote: > "Nigel J. Andrews" <nandrews@investsystems.co.uk> writes: > > I have this query which used to yield this EXPLAIN ANALYZE > > [reformated] output: > > Uh, *which* query, exactly? Hmmm...I suppose I should have written 'I have a query...' Never mind I'll repost the whole message along with the query, just so that it's all together for easier reference. The query refered to in the post below: explain analyze select u.name , p.session_id , p.post_number , to_char(p.time,'Dy, Mon DD YYYY HH:MIam ET') from chat_post p , chat_user u where p.poster_id = u.id AND p.time >= 'epoch'::timestamptz + '959904000 seconds'::interval and p.time <= 'epoch'::timestamptz + '1023667200 seconds'::interval and ( u.lower_name = 'thrifty' OR u.lower_name = 'hope1' ) order by p.time --- >From nandrews@investsystems.co.uk Fri Aug 9 04:11:40 2002 Date: Fri, 9 Aug 2002 03:49:00 +0100 (BST) From: Nigel J. Andrews <nandrews@investsystems.co.uk> To: pgsql-general@postgresql.org Subject: [GENERAL] The standard 'why does it take so long' question I have this query which used to yield this EXPLAIN ANALYZE [reformated] output: Sort (cost=12830.25..12830.25 rows=391 width=26) (actual time=39966.50..40305.70 rows=26982 loops=1) -> Nested Loop (cost=0.00..12813.40 rows=391 width=26) (actual time=69.16..34152.78 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx , chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=1.06..65.62 rows=2 loops=1) -> Index Scan using chat_post_usertime_idx on chat_post p (cost=0.00..6383.72 rows=1638 width=14) (actual time=72.31..10764.40 rows=13491 loops=2) Total runtime: 40739.10 msec where chat_post_usertime_idx is from: CREATE INDEX blah blah ... btree(poster_id,time) After adding another index chat_post_timeuser_idx, which reverses the order of the two columns in the above index, EXPLAIN ANALYZE yields: Sort (cost=9677.13..9677.13 rows=391 width=26) (actual time=62267.30..62554.49 rows=26982 loops=1) -> Nested Loop (cost=0.00..9660.28 rows=391 width=26) (actual time=174.77..55699.39 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx , chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=37.82..97.44 rows=2 loops=1) -> Index Scan using chat_post_timeuser_idx on chat_post p (cost=0.00..4806.89 rows=1638 width=14) (actual time=328.81..19932.71 rows=13491 loops=2) Total runtime: 62983.64 msec A 50% performance loss. I'm just trying to understand where the extra time comes from. Rearranging these explains into pairs of lines such that the first line of a pair is from the first explain and the second line from the second (works best in a _wide_ window) we can more easily compare things. Sort (cost=12830.25..12830.25 rows=391 width=26) (actual time=39966.50..40305.70 rows=26982 loops=1) Sort (cost=9677.13..9677.13 rows=391 width=26) (actual time=62267.30..62554.49 rows=26982 loops=1) -> Nested Loop (cost=0.00..12813.40 rows=391 width=26) (actual time=69.16..34152.78 rows=26982 loops=1) -> Nested Loop (cost=0.00..9660.28 rows=391 width=26) (actual time=174.77..55699.39 rows=26982 loops=1) -> Index Scan using chat_user_lcasename_idx, chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=1.06..65.62 rows=2 loops=1) -> Index Scan using chat_user_lcasename_idx, chat_user_lcasename_idx on chat_user u (cost=0.00..7.21 rows=2 width=12) (actual time=37.82..97.44 rows=2 loops=1) -> Index Scan using chat_post_usertime_idx on chat_post p (cost=0.00..6383.72 rows=1638 width=14) (actual time=72.31..10764.40 rows=13491 loops=2) -> Index Scan using chat_post_timeuser_idx on chat_post p (cost=0.00..4806.89 rows=1638 width=14) (actual time=328.81..19932.71 rows=13491 loops=2) Total runtime: 40739.10 msec Total runtime: 62983.64 msec It's pretty obvious from this that the index scan on chat_user takes longer when the new index is used on the other table. The index scan of the new index obviously takes longer as well. The first question is why would the index scan on chat_user take significantly longer than before? All I could think of is that the use of the new index has forced more disk reads. Does that sound reasonable and what are the alternatives? The next question is why would the index scan of the new index take significantly longer than before? From pg_class the new index uses 3814 pages and the preexisting one 4191. Therefore, one would have thought that the scan of the new index would take less time since less disk reads...uh oh, I think I may have just thought this out clearer...the new index takes longer to scan because it presumbly has to read more pages of the index to cover the required time interval than the older index because the older index has already narrowed the selection down by the user. Does that sound reasonable? That would then support my supposition about the first question, right? My ignorance will show once more now; why would the index scan on chat_user be impacted by a loss of index pages from shared memory/disk cache? Isn't this scan finished before the one on chat_post starts? Or would that scenario have meant a hash join would be in the explain output? This would go some way to explaining the extra time taken on chat_post if I'm missunderstanding this. I think I'll look up the explain output in the manual again as well. Oh, and before it's asked, the DB has been analyzed after the last data load and there was no change in data between these runs. Also: version ---------------------------------------------------------------------- PostgreSQL 7.2.1 on i386-unknown-freebsd3.3, compiled by GCC 2.7.2.3 I hope I haven't put y'all to sleep. -- Nigel J. Andrews Director --- Logictree Systems Limited Computer Consultants -
Re: The standard 'why does it take so long' question
Joe Conway <mail@joeconway.com> — 2002-08-09T04:19:50Z
Nigel J. Andrews wrote: > The query refered to in the post below: > > explain analyze > select u.name > , p.session_id > , p.post_number > , to_char(p.time,'Dy, Mon DD YYYY HH:MIam ET') > from chat_post p > , chat_user u > where > p.poster_id = u.id > AND > p.time >= 'epoch'::timestamptz + '959904000 seconds'::interval > and > p.time <= 'epoch'::timestamptz + '1023667200 seconds'::interval > and > ( u.lower_name = 'thrifty' OR u.lower_name = 'hope1' ) > order by p.time > I'm not sure I can answer your detailed questions, but if you're really searching for a way to make this query run faster, it strikes me that I didn't see any evidence of an index on p.poster_id. It looks to me like that would speed this query significantly. For example, I just experimented here with a header/detail query similar to yours, and found that without an index on the foreign key field, the time for the query increased by 1000X (1.74 msec to 1771.95 msec). HTH, Joe
-
Re: The standard 'why does it take so long' question
Tom Lane <tgl@sss.pgh.pa.us> — 2002-08-09T04:36:10Z
"Nigel J. Andrews" <nandrews@investsystems.co.uk> writes: > The first question is why would the index scan on chat_user take > significantly longer than before? I think the indexscan is having to skip over more irrelevant data in the second case. Think about it: you can scan an index range consisting of a single user's posts between times T1 and T2, or you can scan an index range consisting of all posts between times T1 and T2. The second column of the index will save you from actually going to the heap for posts from other users, but you'll still have to pass over those index entries, because the contiguous range of index entries that covers the data you want will include a a lot of posts from other users. What interests me is why the planner chose the second index when it had a choice; I'd have thought its cost models were good enough to handle this subtlety. Can you post the pg_stats rows for the columns in question? regards, tom lane
-
Re: The standard 'why does it take so long' question
Nigel J. Andrews <nandrews@investsystems.co.uk> — 2002-08-09T11:12:43Z
First I'll just say thanks to Joe Conway for the suggestion of an index on the poster_id column. Although I didn't show it I do have an index on that field as well, however, as I understand it the index on (poster_id,time) should fulfil this same function. On Fri, 9 Aug 2002, Tom Lane wrote: > "Nigel J. Andrews" <nandrews@investsystems.co.uk> writes: > > The first question is why would the index scan on chat_user take > > significantly longer than before? > > I think the indexscan is having to skip over more irrelevant data in the > second case. Think about it: you can scan an index range consisting of > a single user's posts between times T1 and T2, or you can scan an index > range consisting of all posts between times T1 and T2. The second > column of the index will save you from actually going to the heap for > posts from other users, but you'll still have to pass over those index > entries, because the contiguous range of index entries that covers the > data you want will include a a lot of posts from other users. That was the idea that popped into my head while I was writing the questions so that certainly seems reasonable to me. > > What interests me is why the planner chose the second index when it > had a choice; I'd have thought its cost models were good enough to > handle this subtlety. Can you post the pg_stats rows for the columns > in question? I really don't know sufficient to be able to see why the stats would favour one index over the other. Although looking at the pg_stats entries below now I notice that the correlation for the time column is 1, compared to 0.058 for the poster_id. As there is a natural order to the data, i.e. it's loaded in time order, I am not entirely surprised that there's a high correlation, just slightly surprised the stats gatherer picked up on it. Note that the poster_ids for the example query are also shown below and are not listed in the most_common_vals array. I've also shown the human understandable values for the time limits in the query and due to the nature/distribution of this column it's unsurprising to find that I managed to pick a time period that didn't include one of the more common times. So, what's making the planner choose the slower index is the correlation figure right? archive=> select * from pg_stats where attname = 'time' or attname = 'poster_id' and tablename = 'chat_post'; tablename | attname | null_frac | avg_width | n_distinct | most_common_vals | most_common_freqs | histogram_bounds | correlation -----------+-----------+-----------+-----------+------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------- chat_post | poster_id | 0 | 2 | 338 | {2149,731,1130,2595,1879,1656,688,1842,2473,1747} | {0.0603333,0.0306667,0.0306667,0.03,0.0286667,0.0276667,0.0273333,0.025,0.02,0.0196667} | {4,252,521,819,1112,1423,1639,1820,2096,2427,2879} | 0.0583958 chat_post | time | 0 | 8 | -0.350654 | {"1998-03-26 11:09:00-05","1999-05-13 00:49:00-04","2000-12-14 13:05:00-05","2001-01-25 12:18:00-05","2002-04-04 11:37:00-05","2002-05-28 15:21:00-04","2002-07-10 09:53:00-04"} | {0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667} | {"1998-03-06 01:26:00-05","1998-08-21 11:00:00-04","1999-02-22 15:15:00-05","1999-07-22 05:37:00-04","2000-01-24 09:53:00-05","2000-10-23 17:45:00-04","2001-02-26 16:22:00-05","2001-06-28 20:19:00-04","2001-12-06 14:06:00-05","2002-04-26 16:05:00-04","2002-08-09 00:10:00-04"} | 1 (2 rows) archive=> select * from chat_user where name in ('thrifty', 'hope1'); id | name | lower_name ------+---------+------------ 2494 | thrifty | thrifty 1112 | hope1 | hope1 (2 rows) archive=> select 'epoch'::timestamptz + '959904000 seconds'::interval as from, 'epoch'::timestamptz + '1023667200 seconds'::interval as to; from | to ------------------------+------------------------ 2000-06-02 01:00:00+01 | 2002-06-10 01:00:00+01 (1 row) Thanks for the input Tom. -- Nigel J. Andrews Director --- Logictree Systems Limited Computer Consultants -
Re: The standard 'why does it take so long' question
Tom Lane <tgl@sss.pgh.pa.us> — 2002-08-09T13:41:16Z
"Nigel J. Andrews" <nandrews@investsystems.co.uk> writes: > I really don't know sufficient to be able to see why the stats would > favour one index over the other. Although looking at the pg_stats > entries below now I notice that the correlation for the time column is > 1, compared to 0.058 for the poster_id. Ah, of course, that would do it. Thinking about it, I see that the system is not really very bright about ordering considerations for multicolumn indexes. On a macro scale, the posterid/time index is poorly correlated with the physical table order --- but when you consider only the set of entries for a single posterid over a small time range, the index is pretty well correlated. The planner doesn't consider that effect, so it mistakenly credits the time/posterid index with much higher correlation and hence lower scan cost than the other. I already had a todo item to reconsider the costing estimates for multicolumn indexes --- will see if we can be smarter about cases like this. regards, tom lane