Re: Query taking too long. Problem reading explain output.

4 okt 2007 kl. 14:30 skrev Alvaro Herrera:

> Henrik wrote:
>
>> Ahh I had exactly 8 joins.
>> Following your suggestion I raised the join_collapse_limit from 8
>> to 10 and
>> the planners decision sure changed but now I have some crazy
>> nested loops.
>> Maybe I have some statistics wrong?
>
> Yeah. The problematic misestimation is exactly the innermost
> indexscan,
> which is wrong by two orders of magnitude:
>
>> -> Index Scan
>> using
>> tbl_file_idx on tbl_file (cost=0.01..8.66 rows=1 width=39) (actual
>> time=0.057..931.546 rows=2223 loops=1)
>> Index Cond:
>> ((lower((file_name)::text) ~>=~ 'index.php'::character varying) AND
>> (lower((file_name)::text) ~<~ 'index.phq'::character varying))
>> Filter:
>> (lower((file_name)::text) ~~ 'index.php%'::text)
>
> This wreaks havoc on the rest of the plan. If this weren't
> misestimated, it wouldn't be using those nested loops.
>
Correct. I changed the statistics to 500 in tbl_file.file_name and
now the statistics is better. But now my big seq scan on
tbl_file_Structure back and I don't know why.
Pasting new explain analyze:

HashAggregate (cost=467442.44..467442.47 rows=3 width=127) (actual
time=25182.056..25182.169 rows=160 loops=1)
-> Hash Join (cost=16106.29..467442.38 rows=3 width=127)
(actual time=7825.803..25181.394 rows=160 loops=1)
Hash Cond: (tbl_file.fk_filetype_id =
tbl_filetype.pk_filetype_id)
-> Hash Join (cost=16079.94..467413.50 rows=184
width=100) (actual time=7793.171..25148.405 rows=160 loops=1)
Hash Cond: (tbl_file_structure.fk_structure_id =
tbl_structure.pk_structure_id)
-> Hash Join (cost=7295.70..458431.45 rows=17419
width=39) (actual time=619.779..23034.828 rows=20166 loops=1)
Hash Cond: (tbl_file_structure.fk_file_id =
tbl_file.pk_file_id)
-> Seq Scan on tbl_file_structure
(cost=0.00..357539.04 rows=18684504 width=16) (actual
time=5.648..12906.913 rows=18684505 loops=1)
-> Hash (cost=7269.04..7269.04 rows=2133
width=39) (actual time=613.852..613.852 rows=2223 loops=1)
-> Bitmap Heap Scan on tbl_file
(cost=62.50..7269.04 rows=2133 width=39) (actual time=14.672..611.803
rows=2223 loops=1)
Filter: (lower((file_name)::text)
~~ 'index.php%'::text)
-> Bitmap Index Scan on
tbl_file_idx (cost=0.00..61.97 rows=2133 width=0) (actual
time=14.205..14.205 rows=2223 loops=1)
Index Cond: ((lower
((file_name)::text) ~>=~ 'index.php'::character varying) AND (lower
((file_name)::text) ~<~ 'index.phq'::character varying))
-> Hash (cost=8601.81..8601.81 rows=14595 width=77)
(actual time=2076.717..2076.717 rows=24571 loops=1)
-> Index Scan using tbl_structure_idx3 on
tbl_structure (cost=0.00..8601.81 rows=14595 width=77) (actual
time=58.620..2050.555 rows=24571 loops=1)
Index Cond: (fk_archive_id = 56)
-> Hash (cost=26.08..26.08 rows=22 width=59) (actual
time=32.624..32.624 rows=22 loops=1)
-> Nested Loop (cost=2.59..26.08 rows=22 width=59)
(actual time=32.503..32.598 rows=22 loops=1)
-> Nested Loop Left Join (cost=2.59..24.64
rows=1 width=41) (actual time=32.332..32.384 rows=1 loops=1)
Filter: ((tbl_job_group.job_group_type =
'B'::bpchar) OR (tbl_job_group.job_group_type IS NULL))
-> Nested Loop Left Join
(cost=2.59..20.20 rows=1 width=49) (actual time=27.919..27.969 rows=1
loops=1)
Join Filter: (tbl_archive.fk_job_id
= tbl_job.pk_job_id)
-> Nested Loop (cost=2.59..13.05
rows=1 width=49) (actual time=27.897..27.904 rows=1 loops=1)
Join Filter:
(tbl_share.pk_share_id = tbl_archive.fk_share_id)
-> Nested Loop
(cost=0.00..6.43 rows=1 width=41) (actual time=19.638..19.642 rows=1
loops=1)
Join Filter:
(tbl_computer.pk_computer_id = tbl_share.fk_computer_id)
-> Seq Scan on
tbl_computer (cost=0.00..5.16 rows=1 width=20) (actual
time=19.611..19.614 rows=1 loops=1)
Filter:
((computer_name)::text = 'SOLARIS2'::text)
-> Seq Scan on
tbl_share (cost=0.00..1.12 rows=12 width=29) (actual
time=0.011..0.021 rows=12 loops=1)
-> Bitmap Heap Scan on
tbl_archive (cost=2.59..6.60 rows=1 width=24) (actual
time=8.255..8.255 rows=1 loops=1)
Recheck Cond: (56 =
pk_archive_id)
Filter: archive_complete
-> Bitmap Index Scan
on tbl_archive_pkey (cost=0.00..2.59 rows=1 width=0) (actual
time=8.250..8.250 rows=1 loops=1)
Index Cond: (56 =
pk_archive_id)
-> Seq Scan on tbl_job
(cost=0.00..6.51 rows=51 width=16) (actual time=0.003..0.034 rows=51
loops=1)
-> Index Scan using tbl_job_group_pkey
on tbl_job_group (cost=0.00..4.42 rows=1 width=13) (actual
time=4.408..4.410 rows=1 loops=1)
Index Cond:
(tbl_job.fk_job_group_id = tbl_job_group.pk_job_group_id)
-> Seq Scan on tbl_filetype (cost=0.00..1.22
rows=22 width=18) (actual time=0.169..0.178 rows=22 loops=1)
Total runtime: 25182.626 ms

Thanks.,
Henrik
> --
> Alvaro Herrera http://
> www.CommandPrompt.com/
> PostgreSQL Replication, Consulting, Custom Development, 24x7 support