Hi all. I have a strange (and serious) problem with an application
ported from postgres 8.0 to 8.1.
The old installation is postgresql-8.0.4-2.FC4.1 running on a Fedora 4,
the new one is postgresql-8.1.4-1.FC5.1 running on a fedora 5.
Some query is now _very_ slow. I've found some deep differences between
query plans.
As example. The query is:
select count(*) from orario_ap join registrazioni using(treno, data)
join personale using(personale_id) join ruoli using(ruolo_id) where
data=today_or) where data=today_orario();
orario_ap is a view.
On 8.0 the query runs in 138.146 ms
On 8.1 the query runs in 6761.112 ms
On 8.1 with nested loops disabled: 63.184 ms
This is not the only query affected.
Two notes: please cc answer directly to me, and I'm sorry, my english is
alpha version.
On a 8.0 the plan is:
railcomm04=# explain analyze select count(*) from orario_ap join
registrazioni using(treno, data) join personale using(personale_id) join
ruoli using(ruolo_id) where data=today_or) where data=today_orario();
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=1106.77..1106.77 rows=1 width=0) (actual
time=137.786..137.787 rows=1 loops=1)
-> Merge Join (cost=1088.96..1105.66 rows=444 width=0) (actual
time=124.173..137.190 rows=349 loops=1)
Merge Cond: (("outer".tipo_treno = "inner".tipo_treno) AND
("outer".num_treno = "inner".num_treno) AND ("outer".orario =
"inner".orario))
-> Sort (cost=574.10..575.09 rows=395 width=26) (actual
time=97.647..98.010 rows=349 loops=1)
Sort Key: o1.tipo_treno, o1.num_treno, o1.orario
-> Hash Join (cost=28.45..557.06 rows=395 width=26)
(actual time=35.326..93.415 rows=349 loops=1)
Hash Cond: ("outer".ruolo_id = "inner".ruolo_id)
-> Hash Join (cost=27.41..550.10 rows=395
width=30) (actual time=12.827..69.411 rows=349 loops=1)
Hash Cond: ("outer".personale_id =
"inner".personale_id)
-> Hash Join (cost=12.85..529.61 rows=395
width=34) (actual time=10.453..65.365 rows=349 loops=1)
Hash Cond: ("outer".treno =
"inner".treno)
-> Seq Scan on orario o1
(cost=0.00..504.38 rows=843 width=33) (actual time=3.691..57.487
rows=797 loops=1)
Filter: ((seq_fermata = 1) AND
(data = date((now() - '02:00:00'::interval))))
-> Hash (cost=11.98..11.98 rows=349
width=19) (actual time=2.665..2.665 rows=0 loops=1)
-> Seq Scan on registrazioni
(cost=0.00..11.98 rows=349 width=19) (actual time=0.029..2.042 rows=349
loops=1)
Filter: (date((now() -
'02:00:00'::interval)) = data)
-> Hash (cost=12.85..12.85 rows=685
width=4) (actual time=2.350..2.350 rows=0 loops=1)
-> Seq Scan on personale
(cost=0.00..12.85 rows=685 width=4) (actual time=0.005..1.350 rows=685
loops=1)
-> Hash (cost=1.03..1.03 rows=3 width=4) (actual
time=22.479..22.479 rows=0 loops=1)
-> Seq Scan on ruoli (cost=0.00..1.03
rows=3 width=4) (actual time=22.461..22.468 rows=3 loops=1)
-> Sort (cost=514.86..516.94 rows=831 width=26) (actual
time=26.493..27.490 rows=949 loops=1)
Sort Key: o2.tipo_treno, o2.num_treno, o2.orario
-> Seq Scan on orario o2 (cost=0.00..474.56 rows=831
width=26) (actual time=0.056..17.398 rows=797 loops=1)
Filter: ((orario_partenza IS NULL) AND (date((now()
- '02:00:00'::interval)) = data))
Total runtime: 138.146 ms
On a standard 8.1 is:
railcomm04=# explain analyze select count(*) from orario_ap join
registrazioni using(treno, data) join personale using(personale_id) join
ruoli using(ruolo_id) where data=today_orario();
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=500.45..500.46 rows=1 width=0) (actual
time=6760.876..6760.877 rows=1 loops=1)
-> Nested Loop (cost=0.00..500.44 rows=1 width=0) (actual
time=5.915..6759.550 rows=349 loops=1)
Join Filter: (("outer".orario = "inner".orario) AND
("outer".num_treno = "inner".num_treno) AND ("outer".tipo_treno =
"inner".tipo_treno))
-> Nested Loop (cost=0.00..25.87 rows=1 width=72) (actual
time=0.124..42.617 rows=349 loops=1)
-> Nested Loop (cost=0.00..20.15 rows=1 width=76)
(actual time=0.106..34.330 rows=349 loops=1)
-> Nested Loop (cost=0.00..14.12 rows=1 width=40)
(actual time=0.045..12.037 rows=349 loops=1)
Join Filter: ("outer".ruolo_id =
"inner".ruolo_id)
-> Seq Scan on registrazioni
(cost=0.00..11.98 rows=2 width=44) (actual time=0.025..2.315 rows=349
loops=1)
Filter: (date((now() -
'02:00:00'::interval)) = data)
-> Seq Scan on ruoli (cost=0.00..1.03
rows=3 width=4) (actual time=0.003..0.009 rows=3 loops=349)
-> Index Scan using orario_pkey on orario o1
(cost=0.00..6.02 rows=1 width=104) (actual time=0.053..0.056 rows=1
loops=349)
Index Cond: ((o1.treno = "outer".treno) AND
(o1.seq_fermata = 1))
Filter: (data = date((now() -
'02:00:00'::interval)))
-> Index Scan using personale_pkey on personale
(cost=0.00..5.71 rows=1 width=4) (actual time=0.013..0.017 rows=1
loops=349)
Index Cond: ("outer".personale_id =
personale.personale_id)
-> Seq Scan on orario o2 (cost=0.00..474.56 rows=1 width=72)
(actual time=0.030..17.784 rows=797 loops=349)
Filter: ((orario_partenza IS NULL) AND (date((now() -
'02:00:00'::interval)) = data))
Total runtime: 6761.112 ms
On a 8.1 with nested loops disabled:
railcomm04=# explain analyze select count(*) from orario_ap join
registrazioni using(treno, data) join personale using(personale_id) join
ruoli using(ruolo_id) where data=today_orario();
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=802.82..802.83 rows=1 width=0) (actual
time=62.309..62.310 rows=1 loops=1)
-> Hash Join (cost=328.23..802.82 rows=1 width=0) (actual
time=44.443..61.867 rows=349 loops=1)
Hash Cond: (("outer".orario = "inner".orario) AND
("outer".num_treno = "inner".num_treno) AND ("outer".tipo_treno =
"inner".tipo_treno))
-> Seq Scan on orario o2 (cost=0.00..474.56 rows=1 width=72)
(actual time=0.068..16.558 rows=797 loops=1)
Filter: ((orario_partenza IS NULL) AND (date((now() -
'02:00:00'::interval)) = data))
-> Hash (cost=328.22..328.22 rows=1 width=72) (actual
time=38.479..38.479 rows=349 loops=1)
-> Hash Join (cost=29.33..328.22 rows=1 width=72)
(actual time=6.700..37.530 rows=349 loops=1)
Hash Cond: ("outer".treno = "inner".treno)
-> Index Scan using orario_pkey on orario o1
(cost=0.00..298.88 rows=1 width=104) (actual time=0.069..29.033 rows=797
loops=1)
Index Cond: (seq_fermata = 1)
Filter: (data = date((now() -
'02:00:00'::interval)))
-> Hash (cost=29.32..29.32 rows=1 width=36)
(actual time=6.595..6.595 rows=349 loops=1)
-> Hash Join (cost=13.04..29.32 rows=1
width=36) (actual time=3.361..5.887 rows=349 loops=1)
Hash Cond: ("outer".personale_id =
"inner".personale_id)
-> Seq Scan on personale
(cost=0.00..12.85 rows=685 width=4) (actual time=0.013..1.098 rows=685
loops=1)
-> Hash (cost=13.04..13.04 rows=1
width=40) (actual time=3.301..3.301 rows=349 loops=1)
-> Hash Join (cost=1.04..13.04
rows=1 width=40) (actual time=0.090..2.602 rows=349 loops=1)
Hash Cond:
("outer".ruolo_id = "inner".ruolo_id)
-> Seq Scan on
registrazioni (cost=0.00..11.98 rows=2 width=44) (actual
time=0.025..1.465 rows=349 loops=1)
Filter: (date((now()
- '02:00:00'::interval)) = data)
-> Hash (cost=1.03..1.03
rows=3 width=4) (actual time=0.040..0.040 rows=3 loops=1)
-> Seq Scan on ruoli
(cost=0.00..1.03 rows=3 width=4) (actual time=0.014..0.025 rows=3
loops=1)
Total runtime: 63.184 ms
Regards,
Gabriele
