Обсуждение: Extremely slow DELETE with cascade foreign keys

Поиск
Список
Период
Сортировка

Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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.

Re: Extremely slow DELETE with cascade foreign keys

От
Tom Lane
Дата:
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

Re: Extremely slow DELETE with cascade foreign keys

От
Alvaro Herrera
Дата:
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

Re: Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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.

Re: Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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 :)

Re: Extremely slow DELETE with cascade foreign keys

От
Tom Lane
Дата:
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

Re: Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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 :)

Re: Extremely slow DELETE with cascade foreign keys

От
Alvaro Herrera
Дата:
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

Re: Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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
>
>

Re: Extremely slow DELETE with cascade foreign keys

От
Rodrigo Rosenfeld Rosas
Дата:
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 :)

Чтобы сделать работу с сайтом удобнее, мы используем cookie и аналитический сервис «Яндекс.Метрика». Продолжая пользоваться сайтом, вы соглашаетесь с их использованием.