Re: 500x speed-down: Wrong statistics!

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Tom Lane wrote:
Alessandro Baretta <a.baretta@xxxxxxxxxxxxxxx> writes:

Tom Lane wrote:

I'm curious to see how many rows the planner thinks this will produce,
and whether it will use the index or not.
dmd-freerp-1-alex=# EXPLAIN ANALYZE SELECT * FROM articolo WHERE articolo.xdbs_modified > '2006-01-08 18:25:00+01';
                                                                QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------
Index Scan using articolo_modified_index on articolo (cost=0.00..3914.91 rows=17697 width=653) (actual time=0.032..0.032 rows=0 loops=1)
   Index Cond: (xdbs_modified > '2006-01-08 18:25:00'::timestamp without time zone)
 Total runtime: 0.150 ms
(3 rows)


Well, there's your problem: 17697 rows estimated vs 0 actual.  With a
closer row estimate it would've probably done the right thing for the
join problem.

Hmmm, what you are telling me is very interesting, Tom. So, let me see if I got this straight: the first 'rows=... in the result from EXPLAIN ANALYZE gives me estimates, while the second gives the actual cardinality of the selected record set. Correct? If this is true, two questions arise: why is the estimated number of rows completele wrong, and why, given such a large estimated record set does PostgreSQL schedule an Index Scan as opposed to a Seq Scan?


>
> How many rows are really in the table, anyway?  Could we see the
> pg_stats row for articolo.xdbs_modified?

dmd-freerp-1-alex=# select count(*) from articolo;
 count
-------
 53091
(1 row)

dmd-freerp-1-alex=# explain analyze select * from articolo;
                                                   QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Seq Scan on articolo (cost=0.00..1439.91 rows=53091 width=653) (actual time=0.013..151.189 rows=53091 loops=1)
 Total runtime: 295.152 ms
(2 rows)

Now let me get the pg_stats for xdbs_modified.

dmd-freerp-1-alex=# select * from pg_stats where tablename = 'articolo' and attname = 'xdbs_modified'; schemaname | tablename | attname | null_frac | avg_width | n_distinct | most_common_vals | most_common_freqs | histogram_bounds | correlation
------------+-----------+---------------+-----------+-----------+------------+--------------------------------+-------------------+------------------+-------------
public | articolo | xdbs_modified | 0 | 8 | 1 | {"2006-01-10 08:12:58.605327"} | {1} | | 1
(1 row)

For sake of simplicity I have re-timestamped all tuples in the table with the current timestamp, as you can see above. Now, obviously, the planner must estimate ~0 rows for queries posing a selection condition on xdbs_modified, for any value other than "2006-01-10 08:12:58.605327". Let me try selecting from articolo first.

dmd-freerp-1-alex=# EXPLAIN ANALYZE SELECT * FROM articolo WHERE articolo.xdbs_modified > '2006-01-10 18:25:00+01';
                                                             QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
Index Scan using articolo_modified_index on articolo (cost=0.00..2.01 rows=1 width=653) (actual time=0.139..0.139 rows=0 loops=1)
   Index Cond: (xdbs_modified > '2006-01-10 18:25:00'::timestamp without time zone)
 Total runtime: 0.257 ms
(3 rows)

The planner produces a sensible estimate of the number of rows and consequently chooses the appropriate query plan. Now, the join.

dmd-freerp-1-alex=# explain analyze SELECT * FROM articolo JOIN ubicazione USING (id_ente, id_produttore, id_articolo) WHERE articolo.id_ente = 'dmd' AND allarme IS NULL AND manutenzione IS NULL AND articolo.xdbs_modified > '2006-01-10 18:25:00+01';

QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.00..5.05 rows=1 width=1146) (actual time=0.043..0.043 rows=0 loops=1) -> Index Scan using articolo_modified_index on articolo (cost=0.00..2.02 rows=1 width=653) (actual time=0.035..0.035 rows=0 loops=1) Index Cond: (xdbs_modified > '2006-01-10 18:25:00'::timestamp without time zone)
         Filter: (id_ente = 'dmd'::text)
-> Index Scan using ubicazione_fkey_articolo on ubicazione (cost=0.00..3.02 rows=1 width=536) (never executed) Index Cond: (('dmd'::text = ubicazione.id_ente) AND ("outer".id_produttore = ubicazione.id_produttore) AND ("outer".id_articolo = ubicazione.id_articolo))
         Filter: ((allarme IS NULL) AND (manutenzione IS NULL))
 Total runtime: 0.382 ms
(8 rows)

Dear Tom, you're my hero! I have no clue as to how or why the statistics were wrong yesterday--as I vacuum-analyzed continuously out of lack of any better idea--and I was stupid enough to re-timestamp everything before selecting from pg_stats. Supposedly, the timestamps in the table were a random sampling taken from the month of December 2005, so that any date in January would be greater than all the timestamps in xdbs_modified. There must a bug in the my rule/trigger system, which is responsible to maintain these timestamps as appropriate.

			regards, tom lane


Thank you very much Tom and Matteo. Your help has been very precious to me. Thanks to your wisdom, my application will now have a 500x speed boost on a very common class of queries.

The end result is the following query plan, allowing me to rapidly select only the tuples in a join which have changed since the application last updated its notion of this dataset.

dmd-freerp-1-alex=# explain analyze SELECT * FROM articolo JOIN ubicazione USING (id_ente, id_produttore, id_articolo) WHERE articolo.id_ente = 'dmd' AND allarme IS NULL AND manutenzione IS NULL AND articolo.xdbs_modified > '2006-01-10 18:25:00+01' UNION SELECT * FROM articolo JOIN ubicazione USING (id_ente, id_produttore, id_articolo) WHERE articolo.id_ente = 'dmd' AND allarme IS NULL AND manutenzione IS NULL AND ubicazione.xdbs_modified > '2006-01-10 18:25:00+01';
           QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=11.13..11.39 rows=2 width=1146) (actual time=0.519..0.519 rows=0 loops=1) -> Sort (cost=11.13..11.14 rows=2 width=1146) (actual time=0.512..0.512 rows=0 loops=1) Sort Key: id_ente, id_produttore, id_articolo, bigoid, metadata, finalized, xdbs_created, xdbs_modified, barcode, tipo, venditore_id_ente, id_prodotto, aggregato_id_ente, aggregato_id_produttore, aggregato_id_articolo, descr, url, datasheet, scheda_sicurezza, peso, lunghezza, larghezza, altezza, volume, max_strati, um, bigoid, metadata, finalized, xdbs_created, xdbs_modified, barcode, tipo, id_magazzino, id_settore, id_area, id_ubicazione, flavor, peso_max, lunghezza, larghezza, altezza, volume_max, inventario, allarme, manutenzione, quantita, in_prelievo, in_deposito, lotto, scadenza -> Append (cost=0.00..11.12 rows=2 width=1146) (actual time=0.305..0.305 rows=0 loops=1) -> Subquery Scan "*SELECT* 1" (cost=0.00..5.06 rows=1 width=1146) (actual time=0.157..0.157 rows=0 loops=1) -> Nested Loop (cost=0.00..5.05 rows=1 width=1146) (actual time=0.149..0.149 rows=0 loops=1) -> Index Scan using articolo_modified_index on articolo (cost=0.00..2.02 rows=1 width=653) (actual time=0.142..0.142 rows=0 loops=1) Index Cond: (xdbs_modified > '2006-01-10 18:25:00'::timestamp without time zone)
                                 Filter: (id_ente = 'dmd'::text)
-> Index Scan using ubicazione_fkey_articolo on ubicazione (cost=0.00..3.02 rows=1 width=536) (never executed) Index Cond: (('dmd'::text = ubicazione.id_ente) AND ("outer".id_produttore = ubicazione.id_produttore) AND ("outer".id_articolo = ubicazione.id_articolo)) Filter: ((allarme IS NULL) AND (manutenzione IS NULL)) -> Subquery Scan "*SELECT* 2" (cost=0.00..6.06 rows=1 width=1146) (actual time=0.137..0.137 rows=0 loops=1) -> Nested Loop (cost=0.00..6.05 rows=1 width=1146) (actual time=0.131..0.131 rows=0 loops=1) -> Index Scan using ubicazione_modified_index on ubicazione (cost=0.00..3.02 rows=1 width=536) (actual time=0.123..0.123 rows=0 loops=1) Index Cond: (xdbs_modified > '2006-01-10 18:25:00'::timestamp without time zone) Filter: ((allarme IS NULL) AND (manutenzione IS NULL) AND ('dmd'::text = id_ente)) -> Index Scan using articolo_pkey on articolo (cost=0.00..3.02 rows=1 width=653) (never executed) Index Cond: ((articolo.id_ente = 'dmd'::text) AND (articolo.id_produttore = "outer".id_produttore) AND (articolo.id_articolo = "outer".id_articolo))
 Total runtime: 1.609 ms
(20 rows)

Since the previous approach used in my application was to select the whole relation every time the user needed to access this data, the above result must be compared with the following naive one.

dmd-freerp-1-alex=# explain analyze SELECT * FROM articolo JOIN ubicazione USING (id_ente, id_produttore, id_articolo) WHERE articolo.id_ente = 'dmd' AND allarme IS NULL AND manutenzione IS NULL; QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.00..1014.49 rows=1 width=1146) (actual time=0.210..283.272 rows=3662 loops=1) -> Seq Scan on ubicazione (cost=0.00..1011.45 rows=1 width=536) (actual time=0.070..51.223 rows=12036 loops=1) Filter: ((allarme IS NULL) AND (manutenzione IS NULL) AND ('dmd'::text = id_ente)) -> Index Scan using articolo_pkey on articolo (cost=0.00..3.02 rows=1 width=653) (actual time=0.008..0.009 rows=0 loops=12036) Index Cond: ((articolo.id_ente = 'dmd'::text) AND (articolo.id_produttore = "outer".id_produttore) AND (articolo.id_articolo = "outer".id_articolo))
 Total runtime: 292.544 ms
(6 rows)

This amounts to a ~200x speedup for the end user.

Alex

--
*********************************************************************
http://www.barettadeit.com/
Baretta DE&IT
A division of Baretta SRL

tel. +39 02 370 111 55
fax. +39 02 370 111 54

Our technology:

The Application System/Xcaml (AS/Xcaml)
<http://www.asxcaml.org/>

The FreerP Project
<http://www.freerp.org/>


[Postgresql General]     [Postgresql PHP]     [PHP Users]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Yosemite]

  Powered by Linux