pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedRe: 500x speed-down: Wrong statistics!
3+ messages / 2 participants
[nested] [flat]
* Re: 500x speed-down: Wrong statistics!
@ 2006-01-10 07:46 Alessandro Baretta <a.baretta@barettadeit.com>
2006-01-10 15:22 ` Re: 500x speed-down: Wrong statistics! Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 3+ messages in thread
From: Alessandro Baretta @ 2006-01-10 07:46 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Matteo Beccati <php@beccati.com>; 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/;
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: 500x speed-down: Wrong statistics!
2006-01-10 07:46 Re: 500x speed-down: Wrong statistics! Alessandro Baretta <a.baretta@barettadeit.com>
@ 2006-01-10 15:22 ` Tom Lane <tgl@sss.pgh.pa.us>
2006-01-11 09:42 ` Re: 500x speed-down: Wrong statistics! Alessandro Baretta <a.baretta@barettadeit.com>
0 siblings, 1 reply; 3+ messages in thread
From: Tom Lane @ 2006-01-10 15:22 UTC (permalink / raw)
To: Alessandro Baretta <a.baretta@barettadeit.com>; +Cc: Matteo Beccati <php@beccati.com>; pgsql-performance
Alessandro Baretta <a.baretta@barettadeit.com> writes:
> 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.
Too bad. I would be interested to find out how, if the stats were
up-to-date, the thing was still getting the row estimate so wrong.
If you manage to get the database back into its prior state please
do send along the pg_stats info.
regards, tom lane
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: 500x speed-down: Wrong statistics!
2006-01-10 07:46 Re: 500x speed-down: Wrong statistics! Alessandro Baretta <a.baretta@barettadeit.com>
2006-01-10 15:22 ` Re: 500x speed-down: Wrong statistics! Tom Lane <tgl@sss.pgh.pa.us>
@ 2006-01-11 09:42 ` Alessandro Baretta <a.baretta@barettadeit.com>
0 siblings, 0 replies; 3+ messages in thread
From: Alessandro Baretta @ 2006-01-11 09:42 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
Tom Lane wrote:
> Alessandro Baretta <a.baretta@barettadeit.com> writes:
>
>>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.
>
>
> Too bad. I would be interested to find out how, if the stats were
> up-to-date, the thing was still getting the row estimate so wrong.
> If you manage to get the database back into its prior state please
> do send along the pg_stats info.
I have some more information on this issue, which clears PostgreSQL's planner of
all suspects. I am observing severe corruption of the bookkeeping fields managed
by the xdbs rule/trigger "complex". I am unable to pinpoint the cause, right
now, but the effect is that after running a few hours' test on the end-user
application (which never interacts directly with xdbs_* fields, and thus cannot
possibly mangle them) most tuples (the older ones, apparently) get thei
timestamps set to NULL. Before vacuum-analyzing the table, yesterday's
statistics were in effect, and the planner used the appropriate indexes. Now,
after vacuum-analyzing the table, the pg_stats row for the xdbs_modified field
no longer exists (!), and the planner has reverted to the Nested Loop Seq Scan
join strategy. Hence, all the vacuum-analyzing I was doing when complaining
against the planner was actually collecting completely screwed statistics, and
this is why the ALTER TABLE ... SET STATISTICS 1000 did not help at all!
Ok. I plead guilty and ask for the clemency of the court. I'll pay my debt with
society with a long term of pl/pgsql code debugging...
Alex
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2006-01-11 09:42 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2006-01-10 07:46 Re: 500x speed-down: Wrong statistics! Alessandro Baretta <a.baretta@barettadeit.com>
2006-01-10 15:22 ` Tom Lane <tgl@sss.pgh.pa.us>
2006-01-11 09:42 ` Alessandro Baretta <a.baretta@barettadeit.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox