Re: Query taking too long. Problem reading explain output. - Mailing list pgsql-performance

From Henrik
Subject Re: Query taking too long. Problem reading explain output.
Date
Msg-id 8DEE0C69-B3A8-4ED5-AECB-4C7C398C8421@mac.se
Whole thread Raw
In response to Re: Query taking too long. Problem reading explain output.  (Alvaro Herrera <alvherre@commandprompt.com>)
Responses Re: Query taking too long. Problem reading explain output.
List pgsql-performance
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


pgsql-performance by date:

Previous
From: Tom Lane
Date:
Subject: Re: quickly getting the top N rows
Next
From: Ben
Date:
Subject: Re: quickly getting the top N rows