Обсуждение: Difference in query plan

I have a database in a production server (8.1.9) with to schema
containing the sames table same index, same every thing, but with
different data. When I execute a query in one schema, it take much more
time to execute then the other schema. I've issue the query plan and
it's different from one schema to the other. I was assuming that is was
because the contents of the table where different so I've try the query
into a test database into another server (8.3.3) and with both schema, I
get the same query plan and they both work fine

I'm wondering where to start searching to fix this problem

Here is my query:

   SELECT bd.component_item_id AS item_id,
          rspec('schema_name', bd.component_item_id,
bd.component_control_id) AS control_id,
          adjustdate(m.date_due - avior.item_leadtime('schema_name',
bd.item_id, bd.control_id, 0)*7, m.date_due) AS date_due,
          bd.item_id AS to_item_id,
          bd.control_id AS to_control_id, m.quantity *
totalquantity(bd.quantity,
                                                                     CASE

WHEN substring(bd.component_item_id, 1, 1) = 'F' THEN bd.size1 + 1

ELSE bd.size1
                                                                     END,

CASE WHEN substring(bd.component_item_id, 1, 1) = 'F' THEN bd.size2 + 1

ELSE bd.size2

END) / bd.quantity_produce * i.mfg_conv_factor AS quantity
   FROM schema_name.mrp m
   JOIN schema_name.bom_detail bd
      ON bd.item_id = m.item_id
      AND bd.control_id = rspec('schema_name', m.item_id, m.control_id)
      AND NOT bd.rework,
        schema_name.item i
   WHERE i.item_id=m.item_id
     AND NOT bd.item_supplied
     AND bd.component_item_id = 'some value' ;


Production server schema 1 query plan:
                                                                   QUERY
PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=569.23..634.43 rows=1 width=121) (actual
time=1032.811..1032.811 rows=0 loops=1)
   ->  Merge Join  (cost=569.23..628.36 rows=1 width=127) (actual
time=1032.806..1032.806 rows=0 loops=1)
         Merge Cond: (("outer"."?column5?" = "inner".item_id) AND
("outer"."?column6?" = "inner".control_id))
         ->  Sort  (cost=488.89..503.62 rows=5892 width=39) (actual
time=1032.736..1032.736 rows=1 loops=1)
               Sort Key: (m.item_id)::text, (rspec('granby'::text,
m.item_id, m.control_id))::text
               ->  Seq Scan on mrp m  (cost=0.00..119.92 rows=5892
width=39) (actual time=0.343..939.462 rows=5892 loops=1)
         ->  Sort  (cost=80.34..80.39 rows=21 width=97) (actual
time=0.059..0.059 rows=0 loops=1)
               Sort Key: bd.item_id, bd.control_id
               ->  Bitmap Heap Scan on bom_detail bd  (cost=2.08..79.87
rows=21 width=97) (actual time=0.038..0.038 rows=0 loops=1)
                     Recheck Cond: ((component_item_id)::text =
'C294301-1'::text)
                     Filter: ((NOT rework) AND (NOT item_supplied))
                     ->  Bitmap Index Scan on i_bomdetail_component
(cost=0.00..2.08 rows=23 width=0) (actual time=0.031..0.031 rows=0 loops=1)
                           Index Cond: ((component_item_id)::text =
'C294301-1'::text)
   ->  Index Scan using pkey_item on item i  (cost=0.00..6.01 rows=1
width=31) (never executed)
         Index Cond: (i.item_id = ("outer".item_id)::text)
 Total runtime: 1034.204 ms
(16 rows)

Production server schema 2 query plan:
                                                                   QUERY
PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=133.42..793.12 rows=1 width=123) (actual
time=0.130..0.130 rows=0 loops=1)
   ->  Merge Join  (cost=133.42..787.05 rows=1 width=130) (actual
time=0.126..0.126 rows=0 loops=1)
         Merge Cond: (("outer".item_id)::text = "inner".item_id)
         Join Filter: ("inner".control_id = (rspec('laval'::text,
"outer".item_id, "outer".control_id))::text)
         ->  Index Scan using pkey_mrp on mrp m  (cost=0.00..634.29
rows=7501 width=40) (actual time=0.013..0.013 rows=1 loops=1)
         ->  Sort  (cost=133.42..133.51 rows=34 width=99) (actual
time=0.105..0.105 rows=0 loops=1)
               Sort Key: bd.item_id
               ->  Bitmap Heap Scan on bom_detail bd  (cost=2.13..132.56
rows=34 width=99) (actual time=0.099..0.099 rows=0 loops=1)
                     Recheck Cond: ((component_item_id)::text =
'C294301-1'::text)
                     Filter: ((NOT rework) AND (NOT item_supplied))
                     ->  Bitmap Index Scan on i_bomdetail_component
(cost=0.00..2.13 rows=37 width=0) (actual time=0.093..0.093 rows=0 loops=1)
                           Index Cond: ((component_item_id)::text =
'C294301-1'::text)
   ->  Index Scan using pkey_item on item i  (cost=0.00..6.01 rows=1
width=29) (never executed)
         Index Cond: (i.item_id = ("outer".item_id)::text)
 Total runtime: 0.305 ms
(15 rows)


Test server schema 1 query plan:
                                                                QUERY
PLAN

-------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=3.43..367.63 rows=1 width=92) (actual
time=0.248..0.248 rows=0 loops=1)
   ->  Nested Loop  (cost=3.43..360.30 rows=1 width=98) (actual
time=0.243..0.243 rows=0 loops=1)
         Join Filter: ((rspec('granby'::text, m.item_id,
m.control_id))::text = bd.control_id)
         ->  Bitmap Heap Scan on bom_detail bd  (cost=3.43..62.59
rows=21 width=74) (actual time=0.240..0.240 rows=0 loops=1)
               Recheck Cond: ((component_item_id)::text = 'C294301-1'::text)
               Filter: ((NOT rework) AND (NOT item_supplied))
               ->  Bitmap Index Scan on i_bomdetail_component
(cost=0.00..3.43 rows=23 width=0) (actual time=0.234..0.234 rows=0 loops=1)
                     Index Cond: ((component_item_id)::text =
'C294301-1'::text)
         ->  Index Scan using i_mrp_mrp_itm on mrp m  (cost=0.00..9.14
rows=19 width=30) (never executed)
               Index Cond: ((m.item_id)::text = bd.item_id)
   ->  Index Scan using pkey_item on item i  (cost=0.00..6.27 rows=1
width=24) (never executed)
         Index Cond: (i.item_id = bd.item_id)
 Total runtime: 0.717 ms
(13 rows)

Test server schema 2 query plan:
                                                                QUERY
PLAN

-------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=3.54..381.94 rows=1 width=92) (actual
time=0.273..0.273 rows=0 loops=1)
   ->  Nested Loop  (cost=3.54..374.61 rows=1 width=100) (actual
time=0.269..0.269 rows=0 loops=1)
         Join Filter: ((rspec('laval'::text, m.item_id,
m.control_id))::text = bd.control_id)
         ->  Bitmap Heap Scan on bom_detail bd  (cost=3.54..99.80
rows=33 width=75) (actual time=0.265..0.265 rows=0 loops=1)
               Recheck Cond: ((component_item_id)::text = 'C294301-1'::text)
               Filter: ((NOT rework) AND (NOT item_supplied))
               ->  Bitmap Index Scan on i_bomdetail_component
(cost=0.00..3.53 rows=36 width=0) (actual time=0.259..0.259 rows=0 loops=1)
                     Index Cond: ((component_item_id)::text =
'C294301-1'::text)
         ->  Index Scan using i_mrp_mrp_itm on mrp m  (cost=0.00..6.74
rows=6 width=31) (never executed)
               Index Cond: ((m.item_id)::text = bd.item_id)
   ->  Index Scan using pkey_item on item i  (cost=0.00..6.28 rows=1
width=21) (never executed)
         Index Cond: (i.item_id = bd.item_id)
 Total runtime: 0.498 ms
(13 rows)


I'm also wondering why in the production server schema 1 query plan, I'm
getting "outer"."?column5?" instead of "outer"."item_id"

It's also to note that schema 1 contain far less date then schema 2 in
the order of 1 to 4

thanks

Patrice Beliveau wrote:
> I have a database in a production server (8.1.9) with to schema
> containing the sames table same index, same every thing, but with
> different data. When I execute a query in one schema, it take much more
> time to execute then the other schema.
[snip]
> I'm wondering where to start searching to fix this problem

> Production server schema 1 query plan:
> Nested Loop  (cost=569.23..634.43 rows=1 width=121) (actual
> time=1032.811..1032.811 rows=0 loops=1)
[snip]
> Total runtime: 1034.204 ms

> Production server schema 2 query plan:
> Nested Loop  (cost=133.42..793.12 rows=1 width=123) (actual
> time=0.130..0.130 rows=0 loops=1)
[snip]
> Total runtime: 0.305 ms

Well there's something strange - the estimated costs are fairly similar
(643.43 vs 793.12) but the times are clearly very different (1034 vs 0.3ms)

The suspicious line from the first plan is:
>               ->  Seq Scan on mrp m  (cost=0.00..119.92 rows=5892
> width=39) (actual time=0.343..939.462 rows=5892 loops=1)

This is taking up almost all the time in the query and yet only seems to
be scanning 5892 rows.

Run a vacuum verbose against table "mrp" and see if it's got a lot of
dead rows. If it has, run VACUUM FULL and REINDEX against it and see if
that solves your problem.

I'm guessing you have / had a long-running transaction interfering with
vacuum on this table, or perhaps a bulk update/delete?

--
  Richard Huxton
  Archonet Ltd

Thanks,

I'm already doing a vacuum full every night on all database, but the REINDEX fix it and now it's working fine

But this raise a question

1) This table is cleared every night and recomputed, does this mean that I should REINDEX every night also

2) Why this thing didn't happen in the other schema

Thanks again

Patrice Beliveau wrote:

> > I have a database in a production server (8.1.9) with to schema
> > containing the sames table same index, same every thing, but with
> > different data. When I execute a query in one schema, it take much more
> > time to execute then the other schema.
>
[snip]

> > I'm wondering where to start searching to fix this problem
>

> > Production server schema 1 query plan:
> > Nested Loop  (cost=569.23..634.43 rows=1 width=121) (actual
> > time=1032.811..1032.811 rows=0 loops=1)
>
[snip]

> > Total runtime: 1034.204 ms
>

> > Production server schema 2 query plan:
> > Nested Loop  (cost=133.42..793.12 rows=1 width=123) (actual
> > time=0.130..0.130 rows=0 loops=1)
>
[snip]

> > Total runtime: 0.305 ms
>

Well there's something strange - the estimated costs are fairly similar
(643.43 vs 793.12) but the times are clearly very different (1034 vs 0.3ms)

The suspicious line from the first plan is:

> >               ->  Seq Scan on mrp m  (cost=0.00..119.92 rows=5892
> > width=39) (actual time=0.343..939.462 rows=5892 loops=1)
>

This is taking up almost all the time in the query and yet only seems to
be scanning 5892 rows.

Run a vacuum verbose against table "mrp" and see if it's got a lot of
dead rows. If it has, run VACUUM FULL and REINDEX against it and see if
that solves your problem.

I'm guessing you have / had a long-running transaction interfering with
vacuum on this table, or perhaps a bulk update/delete?

-- Richard Huxton Archonet Ltd
-- Sent via pgsql-performance mailing list
(pgsql-performance@postgresql.org) To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance .

Patrice Beliveau wrote:
> Thanks,
>
> I'm already doing a vacuum full every night on all database, but the
> REINDEX fix it and now it's working fine

Are you sure it was the REINDEX? The plan was using a sequential scan.

> But this raise a question
>
> 1) This table is cleared every night and recomputed, does this mean that
> I should REINDEX every night also

Looks like you should. Or drop the indexes, load the data, re-create the
indexes, that can be quicker.

> 2) Why this thing didn't happen in the other schema

Have you re-loaded schema1 more often? It might even be the particular
order that rows are loaded - a btree can become "unbalanced" sometimes.

--
  Richard Huxton
  Archonet Ltd