Re: Seeing foreign key lookups in explain output

Marti Raudsepp <marti(at)juffo(dot)org> wrote:

> On Tue, Sep 20, 2011 at 16:12, Marti Raudsepp <marti(at)juffo(dot)org> wrote:
> > On Tue, Sep 20, 2011 at 15:35, Vincent de Phily
> > <vincent(dot)dephily(at)mobile-devices(dot)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°