Re: Seeing foreign key lookups in explain output - Mailing list pgsql-general

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°