Thread: [PGSQL v8.2.5] Similar queries behave differently
Hi all.
On the very same database and session I have two different (but similar)
queries behaving in a very different way as far as timings.
This is the first one:
prove=# explain analyze select d.* from t_vcol natural join v_dati_attuali d
natural join tt_elem where vtab_id='TEST';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=5.65..8562012.60 rows=88104022 width=73) (actual
time=36.579..36.772 rows=7 loops=1)
-> Hash Join (cost=1.19..442967.06 rows=408730 width=73) (actual
time=36.547..36.660 rows=7 loops=1)
Hash Cond: (d.camp_id = t_vcol.camp_id)
-> Nested Loop (cost=0.00..430860.08 rows=1603700 width=73) (actual
time=36.480..36.558 rows=24 loops=1)
-> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 width=8)
(actual time=0.012..0.013 rows=1 loops=1)
-> Index Scan using i_dati_0 on t_dati d (cost=0.00..211.74
rows=827 width=73) (actual time=36.461..36.498 rows=24 loops
Index Cond: (d.elem_id = tt_elem.elem_id)
Filter: dato_flag
-> Hash (cost=1.12..1.12 rows=5 width=15) (actual time=0.039..0.039
rows=5 loops=1)
-> Seq Scan on t_vcol (cost=0.00..1.12 rows=5 width=15)
(actual time=0.015..0.026 rows=5 loops=1)
Filter: (vtab_id = 'TEST'::text)
-> Bitmap Heap Scan on tt_data (cost=4.46..16.62 rows=216 width=8)
(actual time=0.009..0.009 rows=1 loops=7)
Recheck Cond: ((d.dato_validita <= tt_data.data_corr) AND
(d.dato_scadenza > tt_data.data_corr))
-> Bitmap Index Scan on tt_data_pkey (cost=0.00..4.41 rows=216
width=0) (actual time=0.006..0.006 rows=1 loops=7)
Index Cond: ((d.dato_validita <= tt_data.data_corr) AND
(d.dato_scadenza > tt_data.data_corr))
Total runtime: 36.922 ms
(16 rows)
And this is the second one:
prove=# explain analyze SELECT d.* from t_campi_ricerche natural join
v_dati_attuali d natural join tt_rice where rice_id='CODICE';
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=43.29..38167065.82 rows=409498649 width=73) (actual
time=2927.890..56922.415 rows=1 loops=1)
-> Hash Join (cost=38.83..430557.39 rows=1899736 width=73) (actual
time=2915.990..56910.510 rows=1 loops=1)
Hash Cond: (d.dato_t = tt_rice.dato_t)
-> Hash Join (cost=1.15..402765.04 rows=2335285 width=73) (actual
time=191.261..55238.816 rows=2394966 loops=1)
Hash Cond: (d.camp_id = t_campi_ricerche.camp_id)
-> Seq Scan on t_dati d (cost=0.00..326867.12 rows=14011712
width=73) (actual time=16.612..42797.766 rows=14011712 loops
Filter: dato_flag
-> Hash (cost=1.09..1.09 rows=5 width=15) (actual
time=0.053..0.053 rows=5 loops=1)
-> Seq Scan on t_campi_ricerche (cost=0.00..1.09 rows=5
width=15) (actual time=0.031..0.041 rows=5 loops=1)
Filter: (rice_id = 'CODICE'::text)
-> Hash (cost=22.30..22.30 rows=1230 width=32) (actual
time=0.009..0.009 rows=1 loops=1)
-> Seq Scan on tt_rice (cost=0.00..22.30 rows=1230 width=32)
(actual time=0.003..0.004 rows=1 loops=1)
-> Bitmap Heap Scan on tt_data (cost=4.46..16.62 rows=216 width=8)
(actual time=11.885..11.886 rows=1 loops=1)
Recheck Cond: ((d.dato_validita <= tt_data.data_corr) AND
(d.dato_scadenza > tt_data.data_corr))
-> Bitmap Index Scan on tt_data_pkey (cost=0.00..4.41 rows=216
width=0) (actual time=0.033..0.033 rows=1 loops=1)
Index Cond: ((d.dato_validita <= tt_data.data_corr) AND
(d.dato_scadenza > tt_data.data_corr))
Total runtime: 56922.563 ms
(17 rows)
The v_dati_attuali is a view and is common to both queries.
The structure of indexes is on t_vcol and t_campi_ricerche is very similar and
both tt_rice and tt_elem have just one row wirh one field being primary key.
Of course I'd like the second query to behave the same as the first one but
have no clue on how to achieve it.
Is there any hint?
"Reg Me Please" <regmeplease@gmail.com> writes: > -> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 width=8) > (actual time=0.012..0.013 rows=1 loops=1) The discrepancy etween the estimated rows and actual rows makes me think you've not analyzed this table in a long time. It's probably best to analyze the whole database to have a consistent set of statistics and to catch any other old table stats. There could be other misestimations based due to Postgres limitations but first fix the out of date stats and re-post both plans. -- Gregory Stark EnterpriseDB http://www.enterprisedb.com
"Gregory Stark" <stark@enterprisedb.com> writes: > "Reg Me Please" <regmeplease@gmail.com> writes: > >> -> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 width=8) >> (actual time=0.012..0.013 rows=1 loops=1) > > The discrepancy etween the estimated rows and actual rows makes me think > you've not analyzed this table in a long time. It's probably best to analyze > the whole database to have a consistent set of statistics and to catch any > other old table stats. > > There could be other misestimations based due to Postgres limitations but > first fix the out of date stats and re-post both plans. Actually it's pretty clear there are some other bad estimations as well. You should send along the view definition too. And I would recommend you try it with a normal JOIN ON/USING instead of the NATURAL JOIN. It's possible it's joining on some unexpected columns -- though that doesn't really look like it's the case here. -- Gregory Stark EnterpriseDB http://www.enterprisedb.com
Il Thursday 25 October 2007 13:20:40 Gregory Stark ha scritto: > "Gregory Stark" <stark@enterprisedb.com> writes: > > "Reg Me Please" <regmeplease@gmail.com> writes: > >> -> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 > >> width=8) (actual time=0.012..0.013 rows=1 loops=1) > > > > The discrepancy etween the estimated rows and actual rows makes me think > > you've not analyzed this table in a long time. It's probably best to > > analyze the whole database to have a consistent set of statistics and to > > catch any other old table stats. > > > > There could be other misestimations based due to Postgres limitations but > > first fix the out of date stats and re-post both plans. > > Actually it's pretty clear there are some other bad estimations as well. > You should send along the view definition too. > > And I would recommend you try it with a normal JOIN ON/USING instead of the > NATURAL JOIN. It's possible it's joining on some unexpected columns -- > though that doesn't really look like it's the case here. I'm not sure whether my previous message has reached the list. In any case, the tables have been created with a pg_restore and, thus, not much stats should be available not out-of-date ones. I'd actually like to better understand how to compose queries (and indexes) in order to make them appealing to the query planner. -------- Oggetto: Re: [PGSQL v8.2.5] Similar queries behave differently Data: giovedì 25 ottobre 2007 Da: Reg Me Please <regmeplease@gmail.com> A: pgsql-general@postgresql.org Hai all again. Maybe I've solved the problem, but would like to have some hint on "why". In the second query I've substituted the last join (natural join tt_rice) with an additional "where condition". I can do this as I am sure that the tt_rice table will always contain just one row with one field. The main difference with the first query is that in the first case the single row with a single field is a "bigint", while in the second one it is "text". Otherwise the two queries are almost identical, apart the number of result rows and the size of the joined tables. Is there any deeper tutorial on how to read (and understand) the explain analyze output? Many thanks again.
On 10/25/07, Reg Me Please <regmeplease@gmail.com> wrote: > Il Thursday 25 October 2007 13:20:40 Gregory Stark ha scritto: > > "Gregory Stark" <stark@enterprisedb.com> writes: > > > "Reg Me Please" <regmeplease@gmail.com> writes: > > >> -> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 > > >> width=8) (actual time=0.012..0.013 rows=1 loops=1) > > > > > > The discrepancy etween the estimated rows and actual rows makes me think > > > you've not analyzed this table in a long time. It's probably best to > > > analyze the whole database to have a consistent set of statistics and to > > > catch any other old table stats. > > > > > > There could be other misestimations based due to Postgres limitations but > > > first fix the out of date stats and re-post both plans. > > > > Actually it's pretty clear there are some other bad estimations as well. > > You should send along the view definition too. > > > > And I would recommend you try it with a normal JOIN ON/USING instead of the > > NATURAL JOIN. It's possible it's joining on some unexpected columns -- > > though that doesn't really look like it's the case here. > > I'm not sure whether my previous message has reached the list. > > In any case, the tables have been created with a pg_restore and, thus, > not much stats should be available not out-of-date ones. > > I'd actually like to better understand how to compose queries (and indexes) > in order to make them appealing to the query planner. I'm not sure you understand stats in pgsql. The planner makes decsisions based on those stats, expecting them to be up to date. with default or out of date stats, the planner cannot make a good decision. Run analyze on your db, rerun the explain analyze and post the output. without good stats, you can't make a query that's guaranteed to work well, because pgsql is simply guessing about your data distribution.
Hai all again. Maybe I've solved the problem, but would like to have some hint on "why". In the second query I've substituted the last join (natural join tt_rice) with an additional "where condition". I can do this as I am sure that the tt_rice table will always contain just one row with one field. The main difference with the first query is that in the first case the single row with a single field is a "bigint", while in the second one it is "text". Is there any deeper tutorial on how to read (and understand) the explain analyze output? Many thanks again. Il Thursday 25 October 2007 10:17:23 Reg Me Please ha scritto: > Hi all. > On the very same database and session I have two different (but similar) > queries behaving in a very different way as far as timings. > > This is the first one: > > prove=# explain analyze select d.* from t_vcol natural join v_dati_attuali > d natural join tt_elem where vtab_id='TEST'; > QUERY PLAN > --------------------------------------------------------------------------- >-------------------------------------------------------------- Nested Loop > (cost=5.65..8562012.60 rows=88104022 width=73) (actual time=36.579..36.772 > rows=7 loops=1) > -> Hash Join (cost=1.19..442967.06 rows=408730 width=73) (actual > time=36.547..36.660 rows=7 loops=1) > Hash Cond: (d.camp_id = t_vcol.camp_id) > -> Nested Loop (cost=0.00..430860.08 rows=1603700 width=73) > (actual time=36.480..36.558 rows=24 loops=1) > -> Seq Scan on tt_elem (cost=0.00..29.40 rows=1940 > width=8) (actual time=0.012..0.013 rows=1 loops=1) > -> Index Scan using i_dati_0 on t_dati d > (cost=0.00..211.74 rows=827 width=73) (actual time=36.461..36.498 rows=24 > loops > Index Cond: (d.elem_id = tt_elem.elem_id) > Filter: dato_flag > -> Hash (cost=1.12..1.12 rows=5 width=15) (actual > time=0.039..0.039 rows=5 loops=1) > -> Seq Scan on t_vcol (cost=0.00..1.12 rows=5 width=15) > (actual time=0.015..0.026 rows=5 loops=1) > Filter: (vtab_id = 'TEST'::text) > -> Bitmap Heap Scan on tt_data (cost=4.46..16.62 rows=216 width=8) > (actual time=0.009..0.009 rows=1 loops=7) > Recheck Cond: ((d.dato_validita <= tt_data.data_corr) AND > (d.dato_scadenza > tt_data.data_corr)) > -> Bitmap Index Scan on tt_data_pkey (cost=0.00..4.41 rows=216 > width=0) (actual time=0.006..0.006 rows=1 loops=7) > Index Cond: ((d.dato_validita <= tt_data.data_corr) AND > (d.dato_scadenza > tt_data.data_corr)) > Total runtime: 36.922 ms > (16 rows) > > And this is the second one: > prove=# explain analyze SELECT d.* from t_campi_ricerche natural join > v_dati_attuali d natural join tt_rice where rice_id='CODICE'; > QUERY PLAN > --------------------------------------------------------------------------- >-------------------------------------------------------------- Nested Loop > (cost=43.29..38167065.82 rows=409498649 width=73) (actual > time=2927.890..56922.415 rows=1 loops=1) > -> Hash Join (cost=38.83..430557.39 rows=1899736 width=73) (actual > time=2915.990..56910.510 rows=1 loops=1) > Hash Cond: (d.dato_t = tt_rice.dato_t) > -> Hash Join (cost=1.15..402765.04 rows=2335285 width=73) > (actual time=191.261..55238.816 rows=2394966 loops=1) > Hash Cond: (d.camp_id = t_campi_ricerche.camp_id) > -> Seq Scan on t_dati d (cost=0.00..326867.12 > rows=14011712 width=73) (actual time=16.612..42797.766 rows=14011712 loops > Filter: dato_flag > -> Hash (cost=1.09..1.09 rows=5 width=15) (actual > time=0.053..0.053 rows=5 loops=1) > -> Seq Scan on t_campi_ricerche (cost=0.00..1.09 > rows=5 width=15) (actual time=0.031..0.041 rows=5 loops=1) > Filter: (rice_id = 'CODICE'::text) > -> Hash (cost=22.30..22.30 rows=1230 width=32) (actual > time=0.009..0.009 rows=1 loops=1) > -> Seq Scan on tt_rice (cost=0.00..22.30 rows=1230 > width=32) (actual time=0.003..0.004 rows=1 loops=1) > -> Bitmap Heap Scan on tt_data (cost=4.46..16.62 rows=216 width=8) > (actual time=11.885..11.886 rows=1 loops=1) > Recheck Cond: ((d.dato_validita <= tt_data.data_corr) AND > (d.dato_scadenza > tt_data.data_corr)) > -> Bitmap Index Scan on tt_data_pkey (cost=0.00..4.41 rows=216 > width=0) (actual time=0.033..0.033 rows=1 loops=1) > Index Cond: ((d.dato_validita <= tt_data.data_corr) AND > (d.dato_scadenza > tt_data.data_corr)) > Total runtime: 56922.563 ms > (17 rows) > > > The v_dati_attuali is a view and is common to both queries. > The structure of indexes is on t_vcol and t_campi_ricerche is very similar > and both tt_rice and tt_elem have just one row wirh one field being primary > key. > > Of course I'd like the second query to behave the same as the first one but > have no clue on how to achieve it. > > Is there any hint?