Re: strange performance regression between 7.4 and 8.1

On 3/1/07, Jeff Frost <jeff(at)frostconsultingllc(dot)com> wrote:
> On Thu, 1 Mar 2007, Alex Deucher wrote:
>
> > here are some examples. Analyze is still running on the new db, I'll
> > post results when that is done. Mostly what our apps do is prepared
> > row selects from different tables:
> > select c1,c2,c3,c4,c5 from t1 where c1='XXX';
> >
> > old server:
> > db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6258261';
> > QUERY PLAN
> > ---------------------------------------------------------------------------------------------------------------------------
> > Index Scan using t1_c2_index on t1 (cost=0.00..166.89 rows=42
> > width=26) (actual time=5.722..5.809 rows=2 loops=1)
> > Index Cond: ((c2)::text = '6258261'::text)
> > Total runtime: 5.912 ms
> > (3 rows)
> >
> > db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6258261';
> > QUERY PLAN
> > ----------------------------------------------------------------------------------------------------------------------------
> > Index Scan using t1_c1_key on t1 (cost=0.00..286.08 rows=72
> > width=26) (actual time=12.423..12.475 rows=12 loops=1)
> > Index Cond: ((c1)::text = '6258261'::text)
> > Total runtime: 12.538 ms
> > (3 rows)
> >
> >
> > new server:
> > db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6258261';
> > QUERY PLAN
> > ----------------------------------------------------------------------------------------------------------------------------
> > Index Scan using t1_c2_index on t1 (cost=0.00..37.63 rows=11
> > width=26) (actual time=33.461..51.377 rows=2 loops=1)
> > Index Cond: ((c2)::text = '6258261'::text)
> > Total runtime: 51.419 ms
> > (3 rows)
> >
> > db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6258261';
> > QUERY PLAN
> > --------------------------------------------------------------------------------------------------------------------------------
> > Index Scan using t1_c1_index on t1 (cost=0.00..630.45 rows=2907
> > width=26) (actual time=45.733..46.271 rows=12 loops=1)
> > Index Cond: ((c1)::text = '6258261'::text)
> > Total runtime: 46.325 ms
> > (3 rows)
>
> Notice the huge disparity here betwen the expected number of rows (2907) and
> the actual rows? That's indicative of needing to run analyze. The time is
> only about 4x the 7.4 runtime and that's with the analyze running merrily
> along in the background. It's probably not as bad off as you think. At least
> this query isn't 10x. :-)
>
> Run these again for us after analyze is complete.

well, while the DB isn't 10x, the application using the DB shoes a 10x
decrease in performance. Pages that used to take 5 seconds to load
take 50 secs (I supposed the problem is compounded as there are
several queries per page.). Anyway, new numbers after the analyze.
Unfortunately, they are improved, but still not great:

old server:
db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6258261';
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c2_index on t1 (cost=0.00..166.89 rows=42
width=26) (actual time=0.204..0.284 rows=2 loops=1)
Index Cond: ((c2)::text = '6258261'::text)
Total runtime: 0.421 ms
(3 rows)

db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6258261';
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c1_key on t1 (cost=0.00..286.08 rows=72
width=26) (actual time=0.299..0.354 rows=12 loops=1)
Index Cond: ((c1)::text = '6258261'::text)
Total runtime: 0.451 ms
(3 rows)

new server:
db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6258261';
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c2_index on t1 (cost=0.00..37.63 rows=11
width=26) (actual time=0.126..0.134 rows=2 loops=1)
Index Cond: ((c2)::text = '6258261'::text)
Total runtime: 0.197 ms
(3 rows)

db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6258261';
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c1_index on t1 (cost=0.00..630.45 rows=2907
width=26) (actual time=5.820..5.848 rows=12 loops=1)
Index Cond: ((c1)::text = '6258261'::text)
Total runtime: 5.899 ms
(3 rows)

Here's another example:
old server:
db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6000001';
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c2_index on t1 (cost=0.00..166.89 rows=42
width=26) (actual time=4.031..55.349 rows=8 loops=1)
Index Cond: ((c2)::text = '6000001'::text)
Total runtime: 55.459 ms
(3 rows)

db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6000001';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c1_key on t1 (cost=0.00..286.08 rows=72
width=26) (actual time=0.183..0.203 rows=4 loops=1)
Index Cond: ((c1)::text = '6000001'::text)
Total runtime: 0.289 ms
(3 rows)

new server:
db=# EXPLAIN ANALYZE select c1,c2 from t1 where c2='6000001';
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c2_index on t1 (cost=0.00..37.63 rows=11
width=26) (actual time=115.412..202.151 rows=8 loops=1)
Index Cond: ((c2)::text = '6000001'::text)
Total runtime: 202.234 ms
(3 rows)

db=# EXPLAIN ANALYZE select c1,c2 from t1 where c1='6000001';
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Index Scan using t1_c1_index on t1 (cost=0.00..630.45 rows=2907
width=26) (actual time=99.811..99.820 rows=4 loops=1)
Index Cond: ((c1)::text = '6000001'::text)
Total runtime: 99.861 ms
(3 rows)

I haven't gotten a chance to restart postgres this the config changes
you suggested yet. The rows have improved for some but not all and
the times are still slow. Any ideas?

Alex