Re: Poor performance with ON DELETE CASCADE

On Sep 27, 4:27 am, t(dot)(dot)(dot)(at)sss(dot)pgh(dot)pa(dot)us (Tom Lane) wrote:
> Conal <Conal(dot)Tu(dot)(dot)(dot)(at)gmail(dot)com> writes:
> > I have a database schema which has a "central" table with several
> > others depending on it. The dependent tables all have foreign key
> > constraints with ON DELETE CASCADE so that I can remove tuples from
> > the "central" table and have the dependent rows removed automatically.
> > This all works, but it's very slow, and I can't see why. The dependent
> > tables are all indexed by this foreign key, so the deletions should be
> > very fast.
>
> Did you recently add the required indexes? Existing releases of
> Postgres cache query plans for FK queries for the life of a session,
> so it seems barely possible that you are just working with a stale
> plan. Another possibility is that you need to ANALYZE the tables
> involved so that the planner knows what it's dealing with.

No I have restarted postgresql, vacuumed and analyzed, and nothing has
helped.

> > Unfortunately EXPLAIN doesn't provide any information about the
> > details of how it executes the cascading deletion; there's no query
> > plan for this, so I can't see why it is taking so long. Is it possible
> > to obtain a query plan for these "cascaded" delete queries?
>
> If you have the log message level cranked up high enough when the FK
> trigger is first fired during a session, it'll log the actual FK query,
> and then you can use PREPARE and EXPLAIN EXECUTE to see how it gets
> planned. (You need to take that route because it'll be a parameterized
> query --- do NOT just plug in some constants and assume you'll get the
> same plan.)

Thanks Tom, but this doesn't seem to be the case. I have cranked up
log_min_messages to debug5 level, and i get a lot of messages, but the
cascaded deletes are not shown in the log at all. Here is a snippet of
the log showing the first occurrence of "DELETE" onwards:

2007-10-04 17:16:55 NZDT LOG: 00000: statement: PREPARE S_9 AS DELETE
FROM topic_map_object WHERE uid=$1
2007-10-04 17:16:55 NZDT LOCATION: exec_parse_message, postgres.c:
1153
2007-10-04 17:16:55 NZDT DEBUG: 00000: StartTransactionCommand
2007-10-04 17:16:55 NZDT LOCATION: start_xact_command, postgres.c:
1996
2007-10-04 17:16:55 NZDT LOG: 00000: statement: <BIND>
2007-10-04 17:16:55 NZDT LOCATION: exec_bind_message, postgres.c:1454
2007-10-04 17:16:55 NZDT LOG: 00000: statement: EXECUTE <unnamed>
[PREPARE: DELETE FROM topic_map_object WHERE uid=$1]
2007-10-04 17:16:55 NZDT LOCATION: exec_execute_message, postgres.c:
1733
2007-10-04 17:16:55 NZDT DEBUG: 00000: ProcessQuery
2007-10-04 17:16:55 NZDT LOCATION: ProcessQuery, pquery.c:128
2007-10-04 17:16:56 NZDT DEBUG: 00000: CommitTransactionCommand
2007-10-04 17:16:56 NZDT LOCATION: finish_xact_command, postgres.c:
2019
2007-10-04 17:16:56 NZDT DEBUG: 00000: StartTransactionCommand
2007-10-04 17:16:56 NZDT LOCATION: start_xact_command, postgres.c:
1996
2007-10-04 17:16:56 NZDT LOG: 00000: statement: <BIND>
2007-10-04 17:16:56 NZDT LOCATION: exec_bind_message, postgres.c:1454
2007-10-04 17:16:56 NZDT LOG: 00000: statement: EXECUTE <unnamed>
[PREPARE: DELETE FROM topic_map_object WHERE uid=$1]
2007-10-04 17:16:56 NZDT LOCATION: exec_execute_message, postgres.c:
1733
2007-10-04 17:16:56 NZDT DEBUG: 00000: ProcessQuery
2007-10-04 17:16:56 NZDT LOCATION: ProcessQuery, pquery.c:128
2007-10-04 17:16:58 NZDT DEBUG: 00000: CommitTransactionCommand
2007-10-04 17:16:58 NZDT LOCATION: finish_xact_command, postgres.c:
2019
2007-10-04 17:16:58 NZDT DEBUG: 00000: StartTransactionCommand
2007-10-04 17:16:58 NZDT LOCATION: start_xact_command, postgres.c:
1996
2007-10-04 17:16:58 NZDT LOG: 00000: statement: <BIND>
2007-10-04 17:16:58 NZDT LOCATION: exec_bind_message, postgres.c:1454
2007-10-04 17:16:58 NZDT LOG: 00000: statement: EXECUTE <unnamed>
[PREPARE: DELETE FROM topic_map_object WHERE uid=$1]
2007-10-04 17:16:58 NZDT LOCATION: exec_execute_message, postgres.c:
1733
2007-10-04 17:16:58 NZDT DEBUG: 00000: ProcessQuery
2007-10-04 17:16:58 NZDT LOCATION: ProcessQuery, pquery.c:128
2007-10-04 17:17:00 NZDT DEBUG: 00000: CommitTransactionCommand
2007-10-04 17:17:00 NZDT LOCATION: finish_xact_command, postgres.c:
2019

The client code is deleting a number of rows from the topic_map_object
table, one at a time.

Any ideas?