Subject: Re: Extremely slow DELETE with cascade foreign keys
From: Rodrigo Rosenfeld Rosas <rr.rosas@gmail.com>
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, pgsql-performance@lists.postgresql.org
References: <20171205174914.7q4x56gii3f626zg@alvherre.pgsql>
 <833f6794-3a02-ca8a-5c95-3f1bcaf686b4@gmail.com>
Message-ID: <49f698a3-e4f3-d4e4-f769-d29b39bbb735@gmail.com>
Date: Tue, 5 Dec 2017 16:17:35 -0200
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
 Thunderbird/52.5.0
MIME-Version: 1.0
In-Reply-To: <833f6794-3a02-ca8a-5c95-3f1bcaf686b4@gmail.com>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit
Content-Language: pt-BR
Precedence: bulk

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 :)