Postgres Pro
Downloads
Home   >   mailing lists

Thread: Seeing foreign key lookups in explain output

Seeing foreign key lookups in explain output

From
Vincent de Phily
Date:
Hi list,

an explain analyze wish :

create table t1(id serial primary key);
create table t2(id serial primary key,
                ref integer references t1(id) on delete cascade);
...insert many rows in both tables...
explain delete from t1 where id < 10000;
...
The explain output will tell me it's using the index on t1's id, but it tells
me nothing about the seqscan that happens on t2 (because I forgot to add an
index on t2.ref).

It isn't the first time I get bitten by this, and I bet I'm not the only one.
The explain tells me everything will work fast, but reallity is 100 times
slower. Is there a way I can extend explain output to show the rest of the
work done behind the scene ? Fixing that performance issue is easy once you
see it, but most people will just look at the explain output and erroneously
conclude "it's as good as it gets".

--
Vincent de Phily

Re: Seeing foreign key lookups in explain output

From
Marti Raudsepp
Date:
On Tue, Sep 20, 2011 at 15:35, Vincent de Phily
<vincent.dephily@mobile-devices.fr> wrote:
> The explain output will tell me it's using the index on t1's id, but it tells
> me nothing about the seqscan that happens on t2 (because I forgot to add an
> index on t2.ref).

+1 for a TODO on adding foreign key trigger time to EXPLAIN ANALYZE output.

Regards,
Marti

Re: Seeing foreign key lookups in explain output

From
Marti Raudsepp
Date:
On Tue, Sep 20, 2011 at 16:12, Marti Raudsepp <marti@juffo.org> wrote:
> On Tue, Sep 20, 2011 at 15:35, Vincent de Phily
> <vincent.dephily@mobile-devices.fr> wrote:
>> The explain output will tell me it's using the index on t1's id, but it tells
>> me nothing about the seqscan that happens on t2 (because I forgot to add an
>> index on t2.ref).
>
> +1 for a TODO on adding foreign key trigger time to EXPLAIN ANALYZE output.

Sorry, that was too hasty. We already have that now in 9.0 and 9.1
(not sure when it was introduced)

create table a as select generate_series(1,10000) i;
create table b as select generate_series(1,10000) i;
alter table a add primary key (i);
alter table b add foreign key (i) references a (i) on delete cascade;
explain analyze delete from a;

                                                 QUERY PLAN
 -----------------------------------------------------------------------------------------------------------
 Delete  (cost=0.00..145.00 rows=10000 width=6) (actual
time=16.308..16.308 rows=0 loops=1)
   ->  Seq Scan on a  (cost=0.00..145.00 rows=10000 width=6) (actual
time=0.008..2.208 rows=10000 loops=1)
 Trigger for constraint b_i_fkey: time=6324.652 calls=10000
 Total runtime: 6342.406 ms

Notice the line "Trigger for constraint b_i_fkey"

Regards,
Marti

Re: Seeing foreign key lookups in explain output

From
Vincent de Phily
Date:
On Tuesday 20 September 2011 16:32:50 Marti Raudsepp wrote:
> On Tue, Sep 20, 2011 at 16:12, Marti Raudsepp <marti@juffo.org> wrote:
> > +1 for a TODO on adding foreign key trigger time to EXPLAIN ANALYZE
> > output.
> Sorry, that was too hasty. We already have that now in 9.0 and 9.1
> (not sure when it was introduced)
>
> create table a as select generate_series(1,10000) i;
> create table b as select generate_series(1,10000) i;
> alter table a add primary key (i);
> alter table b add foreign key (i) references a (i) on delete cascade;
> explain analyze delete from a;
>
>                                                  QUERY PLAN
>  ---------------------------------------------------------------------------
> -------------------------------- Delete  (cost=0.00..145.00 rows=10000
> width=6) (actual
> time=16.308..16.308 rows=0 loops=1)
>    ->  Seq Scan on a  (cost=0.00..145.00 rows=10000 width=6) (actual
> time=0.008..2.208 rows=10000 loops=1)
>  Trigger for constraint b_i_fkey: time=6324.652 calls=10000
>  Total runtime: 6342.406 ms
>
> Notice the line "Trigger for constraint b_i_fkey"

Ahhh I never spoted that in the changelogs, and haven't upgraded yet. Great :)
Yet another reason to upgrade ASAP. Thanks.

--
Vincent de Phily

Re: Seeing foreign key lookups in explain output

From
Andreas Kretschmer
Date:
Marti Raudsepp <marti@juffo.org> wrote:

> On Tue, Sep 20, 2011 at 16:12, Marti Raudsepp <marti@juffo.org> wrote:
> > On Tue, Sep 20, 2011 at 15:35, Vincent de Phily
> > <vincent.dephily@mobile-devices.fr> wrote:
> >> The explain output will tell me it's using the index on t1's id, but it tells
> >> me nothing about the seqscan that happens on t2 (because I forgot to add an
> >> index on t2.ref).
> >
> > +1 for a TODO on adding foreign key trigger time to EXPLAIN ANALYZE output.
>
> Sorry, that was too hasty. We already have that now in 9.0 and 9.1
> (not sure when it was introduced)
>
> create table a as select generate_series(1,10000) i;
> create table b as select generate_series(1,10000) i;
> alter table a add primary key (i);
> alter table b add foreign key (i) references a (i) on delete cascade;
> explain analyze delete from a;
>
>                                                  QUERY PLAN
>  -----------------------------------------------------------------------------------------------------------
>  Delete  (cost=0.00..145.00 rows=10000 width=6) (actual
> time=16.308..16.308 rows=0 loops=1)
>    ->  Seq Scan on a  (cost=0.00..145.00 rows=10000 width=6) (actual
> time=0.008..2.208 rows=10000 loops=1)
>  Trigger for constraint b_i_fkey: time=6324.652 calls=10000
>  Total runtime: 6342.406 ms
>
> Notice the line "Trigger for constraint b_i_fkey"

Unfortunately, there is no information about the plan for the trigger.
With extra index:

test=*# create index idx_b on b(i);
CREATE INDEX
Time: 10,645 ms
test=*# explain analyze delete from a;
                                                QUERY PLAN
-----------------------------------------------------------------------------------------------------------
 Delete on a  (cost=0.00..140.00 rows=10000 width=6) (actual time=18.881..18.881 rows=0 loops=1)
   ->  Seq Scan on a  (cost=0.00..140.00 rows=10000 width=6) (actual time=0.015..3.800 rows=10000 loops=1)
 Trigger for constraint b_i_fkey: time=231.084 calls=10000
 Total runtime: 254.033 ms


without index:

test=*# explain analyze delete from a;
                                                QUERY PLAN
-----------------------------------------------------------------------------------------------------------
 Delete on a  (cost=0.00..140.00 rows=10000 width=6) (actual time=19.090..19.090 rows=0 loops=1)
   ->  Seq Scan on a  (cost=0.00..140.00 rows=10000 width=6) (actual time=0.014..3.868 rows=10000 loops=1)
 Trigger for constraint b_i_fkey: time=9823.762 calls=10000
 Total runtime: 9846.789 ms
(4 rows)

The same plan, but not the same execution time. Bad...
(version ist 9.1.0)


Andreas
--
Really, I'm not out to destroy Microsoft. That will just be a completely
unintentional side effect.                              (Linus Torvalds)
"If I was god, I would recompile penguin with --enable-fly."   (unknown)
Kaufbach, Saxony, Germany, Europe.              N 51.05082°, E 13.56889°