Re: 500x speed-down: Wrong statistics! - Mailing list pgsql-performance

Tom Lane wrote:
> Alessandro Baretta <a.baretta@barettadeit.com> 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/>