Thread: Extremely slow DELETE with cascade foreign keys
Hi, I think something changed recently in my development environment as I don't recall deletes being so slow before. I've created a new dump and restored to a new database, ran VACUUM FULL ANALYSE and a simple delete takes forever as you can see here: explain analyze delete from field_values where transaction_id=226; QUERY PLAN --------------------------------------------------------------------------------------------------------------------------------------------------------------- Delete on field_values (cost=0.43..257.93 rows=481 width=6) (actual time=367375.805..367375.805 rows=0 loops=1) -> Index Scan using index_field_values_on_transaction_id on field_values (cost=0.43..257.93 rows=481 width=6) (actual time=0.223..4.216 rows=651 loops=1) Index Cond: (transaction_id = 226) Planning time: 0.234 ms Execution time: 367375.882 ms (5 registros) Time: 367377,085 ms (06:07,377) Any ideas on what could be causing this? Could it be an issue with my hard drive? There aren't that many records to delete from the other tables referencing field_values. I've done this sort of operation earlier this year and it was quite fast. Any clues? Thanks in advance, Rodrigo.
Rodrigo Rosenfeld Rosas <rr.rosas@gmail.com> writes:
> Hi, I think something changed recently in my development environment as
> I don't recall deletes being so slow before.
> I've created a new dump and restored to a new database, ran VACUUM FULL
> ANALYSE and a simple delete takes forever as you can see here:
The usual suspect for this is not having an index on some FK referencing
column, thus forcing the FK check trigger to seq-scan the entire
referencing table for each referenced row that is to be deleted.
regards, tom lane
Rodrigo Rosenfeld Rosas wrote: > explain analyze delete from field_values where transaction_id=226; > QUERY PLAN > --------------------------------------------------------------------------------------------------------------------------------------------------------------- > Delete on field_values (cost=0.43..257.93 rows=481 width=6) (actual > time=367375.805..367375.805 rows=0 loops=1) > -> Index Scan using index_field_values_on_transaction_id on > field_values (cost=0.43..257.93 rows=481 width=6) (actual time=0.223..4.216 > rows=651 loops=1) > Index Cond: (transaction_id = 226) > Planning time: 0.234 ms > Execution time: 367375.882 ms > (5 registros) > > Time: 367377,085 ms (06:07,377) Normally this is because you lack indexes on the referencing columns, so the query that scans the table to find the referencing rows is a seqscan. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Em 05-12-2017 14:27, Tom Lane escreveu:
> Rodrigo Rosenfeld Rosas <rr.rosas@gmail.com> writes:
>> Hi, I think something changed recently in my development environment as
>> I don't recall deletes being so slow before.
>> I've created a new dump and restored to a new database, ran VACUUM FULL
>> ANALYSE and a simple delete takes forever as you can see here:
> The usual suspect for this is not having an index on some FK referencing
> column, thus forcing the FK check trigger to seq-scan the entire
> referencing table for each referenced row that is to be deleted.
>
> regards, tom lane
Thanks, indeed that was the case. I manually inspected about a dozen
tables referencing field_values and the last one ("references") was
referenced by another table ("highlighted_texts") and the reference_id
column that has a foreign key on "references"(id) was missing an index.
Good job :)
Best,
Rodrigo.
Em 05-12-2017 14:43, Alvaro Herrera escreveu: > Rodrigo Rosenfeld Rosas wrote: > >> explain analyze delete from field_values where transaction_id=226; >> QUERY PLAN >> --------------------------------------------------------------------------------------------------------------------------------------------------------------- >> Delete on field_values (cost=0.43..257.93 rows=481 width=6) (actual >> time=367375.805..367375.805 rows=0 loops=1) >> -> Index Scan using index_field_values_on_transaction_id on >> field_values (cost=0.43..257.93 rows=481 width=6) (actual time=0.223..4.216 >> rows=651 loops=1) >> Index Cond: (transaction_id = 226) >> Planning time: 0.234 ms >> Execution time: 367375.882 ms >> (5 registros) >> >> Time: 367377,085 ms (06:07,377) > Normally this is because you lack indexes on the referencing columns, so > the query that scans the table to find the referencing rows is a > seqscan. > Thank you, Álvaro, that was indeed the case, just like Tom Lane suggested as well. I found the missing index and fixed it. Thanks :)
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Rodrigo Rosenfeld Rosas wrote:
>> explain analyze delete from field_values where transaction_id=226;
>> QUERY PLAN
>>
---------------------------------------------------------------------------------------------------------------------------------------------------------------
>> Delete on field_values (cost=0.43..257.93 rows=481 width=6) (actual
>> time=367375.805..367375.805 rows=0 loops=1)
>> -> Index Scan using index_field_values_on_transaction_id on
>> field_values (cost=0.43..257.93 rows=481 width=6) (actual time=0.223..4.216
>> rows=651 loops=1)
>> Index Cond: (transaction_id = 226)
>> Planning time: 0.234 ms
>> Execution time: 367375.882 ms
>> (5 registros)
>>
>> Time: 367377,085 ms (06:07,377)
> Normally this is because you lack indexes on the referencing columns, so
> the query that scans the table to find the referencing rows is a
> seqscan.
Actually though ... the weird thing about this is that I'd expect to
see a separate line in the EXPLAIN output for time spent in the FK
trigger. Where'd that go?
regards, tom lane
Em 05-12-2017 15:25, Tom Lane escreveu: > Alvaro Herrera <alvherre@alvh.no-ip.org> writes: >> Rodrigo Rosenfeld Rosas wrote: >>> explain analyze delete from field_values where transaction_id=226; >>> QUERY PLAN >>> --------------------------------------------------------------------------------------------------------------------------------------------------------------- >>> Delete on field_values (cost=0.43..257.93 rows=481 width=6) (actual >>> time=367375.805..367375.805 rows=0 loops=1) >>> -> Index Scan using index_field_values_on_transaction_id on >>> field_values (cost=0.43..257.93 rows=481 width=6) (actual time=0.223..4.216 >>> rows=651 loops=1) >>> Index Cond: (transaction_id = 226) >>> Planning time: 0.234 ms >>> Execution time: 367375.882 ms >>> (5 registros) >>> >>> Time: 367377,085 ms (06:07,377) >> Normally this is because you lack indexes on the referencing columns, so >> the query that scans the table to find the referencing rows is a >> seqscan. > Actually though ... the weird thing about this is that I'd expect to > see a separate line in the EXPLAIN output for time spent in the FK > trigger. Where'd that go? > > regards, tom lane Yes, I was also hoping to get more insights through the EXPLAIN output :)
Rodrigo Rosenfeld Rosas wrote:
> Em 05-12-2017 15:25, Tom Lane escreveu:
> > > Normally this is because you lack indexes on the referencing columns, so
> > > the query that scans the table to find the referencing rows is a
> > > seqscan.
> > Actually though ... the weird thing about this is that I'd expect to
> > see a separate line in the EXPLAIN output for time spent in the FK
> > trigger. Where'd that go?
>
> Yes, I was also hoping to get more insights through the EXPLAIN output :)
It normally does. Can you show \d of the table containing the FK?
alvherre=# begin; explain analyze delete from pk where a = 505; rollback;
BEGIN
Duración: 0,207 ms
QUERY PLAN
──────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Delete on pk (cost=0.00..8.27 rows=1 width=6) (actual time=0.023..0.023 rows=0 loops=1)
-> Index Scan using pk_pkey on pk (cost=0.00..8.27 rows=1 width=6) (actual time=0.012..0.013 rows=1 loops=1)
Index Cond: (a = 505)
Trigger for constraint fk_a_fkey: time=201.580 calls=1
Total runtime: 201.625 ms
(5 filas)
alvherre=# \d fk
Tabla «public.fk»
Columna │ Tipo │ Modificadores
─────────┼─────────┼───────────────
a │ integer │
Restricciones de llave foránea:
"fk_a_fkey" FOREIGN KEY (a) REFERENCES pk(a) ON DELETE CASCADE
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Em 05-12-2017 15:49, Alvaro Herrera escreveu:
> Rodrigo Rosenfeld Rosas wrote:
>> Em 05-12-2017 15:25, Tom Lane escreveu:
>>>> Normally this is because you lack indexes on the referencing columns, so
>>>> the query that scans the table to find the referencing rows is a
>>>> seqscan.
>>> Actually though ... the weird thing about this is that I'd expect to
>>> see a separate line in the EXPLAIN output for time spent in the FK
>>> trigger. Where'd that go?
>> Yes, I was also hoping to get more insights through the EXPLAIN output :)
> It normally does. Can you show \d of the table containing the FK?
\d highlighted_text
Tabela "public.highlighted_text"
Coluna | Tipo | Collation | Nullable
| Default
--------------+-----------------------------+-----------+----------+----------------------------------------------
id | integer | | not null |
nextval('highlighted_text_id_seq'::regclass)
date_created | timestamp without time zone | | not null |
last_updated | timestamp without time zone | | not null |
reference_id | integer | | not null |
highlighting | text | | |
Índices:
"highlighted_text_pkey" PRIMARY KEY, btree (id)
"highlighted_text_reference_id_idx" btree (reference_id)
Restrições de chave estrangeira:
"fk_highlighted_text_reference" FOREIGN KEY (reference_id)
REFERENCES "references"(id) ON DELETE CASCADE
The highlighted_text_reference_id_idx was previously missing.
begin; explain analyze delete from "references" where id=966539; rollback;
BEGIN
Tempo: 0,466 ms
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
Delete on "references" (cost=0.43..8.45 rows=1 width=6) (actual
time=2.683..2.683 rows=0 loops=1)
-> Index Scan using references_pkey on "references"
(cost=0.43..8.45 rows=1 width=6) (actual time=2.609..2.612 rows=1 loops=1)
Index Cond: (id = 966539)
Planning time: 0.186 ms
Trigger for constraint fk_highlighted_text_reference: time=0.804 calls=1
Execution time: 3.551 ms
(6 registros)
Tempo: 4,791 ms
ROLLBACK
Tempo: 0,316 ms
drop index highlighted_text_reference_id_idx;
DROP INDEX
Tempo: 35,938 ms
begin; explain analyze delete from "references" where id=966539; rollback;
BEGIN
Tempo: 0,494 ms
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
Delete on "references" (cost=0.43..8.45 rows=1 width=6) (actual
time=0.112..0.112 rows=0 loops=1)
-> Index Scan using references_pkey on "references"
(cost=0.43..8.45 rows=1 width=6) (actual time=0.071..0.074 rows=1 loops=1)
Index Cond: (id = 966539)
Planning time: 0.181 ms
Trigger for constraint fk_highlighted_text_reference: time=2513.816
calls=1
Execution time: 2513.992 ms
(6 registros)
Time: 2514,801 ms (00:02,515)
ROLLBACK
Tempo: 0,291 ms
It displayed the spent on the trigger this time. How about deleting the
field values?
begin; explain analyze delete from field_values where
transaction_id=2479; rollback;
BEGIN
Tempo: 0,461 ms
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------
Delete on field_values (cost=0.43..364.98 rows=453 width=6) (actual
time=4.732..4.732 rows=0 loops=1)
-> Index Scan using index_field_values_on_transaction_id on
field_values (cost=0.43..364.98 rows=453 width=6) (actual
time=0.137..0.949 rows=624 loops=1)
Index Cond: (transaction_id = 2479)
Planning time: 0.210 ms
Trigger for constraint field_value_booleans_field_value_id_fkey on
field_values: time=7.953 calls=624
Trigger for constraint field_value_currencies_field_value_id_fkey on
field_values: time=5.548 calls=624
Trigger for constraint field_value_jurisdictions_field_value_id_fkey
on field_values: time=6.376 calls=624
Trigger for constraint fk_field_value_date_range_field_value_id on
field_values: time=5.735 calls=624
Trigger for constraint fk_field_value_dates_field_value_id on
field_values: time=6.316 calls=624
Trigger for constraint fk_field_value_numerics_field_value_id on
field_values: time=6.368 calls=624
Trigger for constraint fk_field_value_options_field_value_id on
field_values: time=6.503 calls=624
Trigger for constraint fk_field_value_strings_field_value_id on
field_values: time=6.794 calls=624
Trigger for constraint fk_field_value_time_spans_field_value_id on
field_values: time=6.332 calls=624
Trigger for constraint fk_references_field_value_id on field_values:
time=7.382 calls=624
Trigger for constraint fk_highlighted_text_reference on references:
time=644994.047 calls=390
Execution time: 645065.326 ms
(16 registros)
Time: 645066,726 ms (10:45,067)
ROLLBACK
Tempo: 0,300 ms
Yeah, for some reason, now I got the relevant trigger hints :) Go figure
out why it didn't work the last time I tried before subscribing to this
list :)
Glad it's working now anyway :)
Thanks,
Rodrigo.
>
> alvherre=# begin; explain analyze delete from pk where a = 505; rollback;
> BEGIN
> Duración: 0,207 ms
> QUERY PLAN
> ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────
> Delete on pk (cost=0.00..8.27 rows=1 width=6) (actual time=0.023..0.023 rows=0 loops=1)
> -> Index Scan using pk_pkey on pk (cost=0.00..8.27 rows=1 width=6) (actual time=0.012..0.013 rows=1 loops=1)
> Index Cond: (a = 505)
> Trigger for constraint fk_a_fkey: time=201.580 calls=1
> Total runtime: 201.625 ms
> (5 filas)
>
> alvherre=# \d fk
> Tabla «public.fk»
> Columna │ Tipo │ Modificadores
> ─────────┼─────────┼───────────────
> a │ integer │
> Restricciones de llave foránea:
> "fk_a_fkey" FOREIGN KEY (a) REFERENCES pk(a) ON DELETE CASCADE
>
>
Em 05-12-2017 16:15, Rodrigo Rosenfeld Rosas escreveu:
> Em 05-12-2017 15:49, Alvaro Herrera escreveu:
>> Rodrigo Rosenfeld Rosas wrote:
>>> Em 05-12-2017 15:25, Tom Lane escreveu:
>>>>> Normally this is because you lack indexes on the referencing
>>>>> columns, so
>>>>> the query that scans the table to find the referencing rows is a
>>>>> seqscan.
>>>> Actually though ... the weird thing about this is that I'd expect to
>>>> see a separate line in the EXPLAIN output for time spent in the FK
>>>> trigger. Where'd that go?
>>> Yes, I was also hoping to get more insights through the EXPLAIN
>>> output :)
>> It normally does. Can you show \d of the table containing the FK?
>
> \d highlighted_text
> Tabela "public.highlighted_text"
> Coluna | Tipo | Collation | Nullable
> | Default
> --------------+-----------------------------+-----------+----------+----------------------------------------------
>
> id | integer | | not null |
> nextval('highlighted_text_id_seq'::regclass)
> date_created | timestamp without time zone | | not null |
> last_updated | timestamp without time zone | | not null |
> reference_id | integer | | not null |
> highlighting | text | | |
> Índices:
> "highlighted_text_pkey" PRIMARY KEY, btree (id)
> "highlighted_text_reference_id_idx" btree (reference_id)
> Restrições de chave estrangeira:
> "fk_highlighted_text_reference" FOREIGN KEY (reference_id)
> REFERENCES "references"(id) ON DELETE CASCADE
>
> The highlighted_text_reference_id_idx was previously missing.
>
> begin; explain analyze delete from "references" where id=966539;
> rollback;
> BEGIN
> Tempo: 0,466 ms
> QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------
>
> Delete on "references" (cost=0.43..8.45 rows=1 width=6) (actual
> time=2.683..2.683 rows=0 loops=1)
> -> Index Scan using references_pkey on "references"
> (cost=0.43..8.45 rows=1 width=6) (actual time=2.609..2.612 rows=1
> loops=1)
> Index Cond: (id = 966539)
> Planning time: 0.186 ms
> Trigger for constraint fk_highlighted_text_reference: time=0.804 calls=1
> Execution time: 3.551 ms
> (6 registros)
>
> Tempo: 4,791 ms
> ROLLBACK
> Tempo: 0,316 ms
>
> drop index highlighted_text_reference_id_idx;
> DROP INDEX
> Tempo: 35,938 ms
>
> begin; explain analyze delete from "references" where id=966539;
> rollback;
> BEGIN
> Tempo: 0,494 ms
> QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------
>
> Delete on "references" (cost=0.43..8.45 rows=1 width=6) (actual
> time=0.112..0.112 rows=0 loops=1)
> -> Index Scan using references_pkey on "references"
> (cost=0.43..8.45 rows=1 width=6) (actual time=0.071..0.074 rows=1
> loops=1)
> Index Cond: (id = 966539)
> Planning time: 0.181 ms
> Trigger for constraint fk_highlighted_text_reference: time=2513.816
> calls=1
> Execution time: 2513.992 ms
> (6 registros)
>
> Time: 2514,801 ms (00:02,515)
> ROLLBACK
> Tempo: 0,291 ms
>
> It displayed the spent on the trigger this time. How about deleting
> the field values?
>
> begin; explain analyze delete from field_values where
> transaction_id=2479; rollback;
> BEGIN
> Tempo: 0,461 ms
> QUERY PLAN
>
---------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Delete on field_values (cost=0.43..364.98 rows=453 width=6) (actual
> time=4.732..4.732 rows=0 loops=1)
> -> Index Scan using index_field_values_on_transaction_id on
> field_values (cost=0.43..364.98 rows=453 width=6) (actual
> time=0.137..0.949 rows=624 loops=1)
> Index Cond: (transaction_id = 2479)
> Planning time: 0.210 ms
> Trigger for constraint field_value_booleans_field_value_id_fkey on
> field_values: time=7.953 calls=624
> Trigger for constraint field_value_currencies_field_value_id_fkey on
> field_values: time=5.548 calls=624
> Trigger for constraint field_value_jurisdictions_field_value_id_fkey
> on field_values: time=6.376 calls=624
> Trigger for constraint fk_field_value_date_range_field_value_id on
> field_values: time=5.735 calls=624
> Trigger for constraint fk_field_value_dates_field_value_id on
> field_values: time=6.316 calls=624
> Trigger for constraint fk_field_value_numerics_field_value_id on
> field_values: time=6.368 calls=624
> Trigger for constraint fk_field_value_options_field_value_id on
> field_values: time=6.503 calls=624
> Trigger for constraint fk_field_value_strings_field_value_id on
> field_values: time=6.794 calls=624
> Trigger for constraint fk_field_value_time_spans_field_value_id on
> field_values: time=6.332 calls=624
> Trigger for constraint fk_references_field_value_id on field_values:
> time=7.382 calls=624
> Trigger for constraint fk_highlighted_text_reference on references:
> time=644994.047 calls=390
> Execution time: 645065.326 ms
> (16 registros)
>
> Time: 645066,726 ms (10:45,067)
> ROLLBACK
> Tempo: 0,300 ms
>
> Yeah, for some reason, now I got the relevant trigger hints :) Go
> figure out why it didn't work the last time I tried before subscribing
> to this list :)
>
> Glad it's working now anyway :)
Just in case you're curious, creating the index took 6s and running the
same delete this time only took 75ms with the index in place :)