Re: Poor performance for delete query

Many thanks for the swift reply Tom, please see additional input below

/Jona

On 24 April 2014 22:29, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Jonatan Evald Buus <jonatan(dot)buus(at)cellpointmobile(dot)com> writes:
> > We're currently having very poor performance for the following delete
> query.
> > DELETE FROM TopTable WHERE id IN (xx, yy, zz);
>
> > We've observed that it takes around 7 seconds under normal load to for
> each
> > row that's being from TopTable and several minutes pr deleted row under
> > heavy load.
>
> I'd really have to bet that you forgot to index one of the referencing
> tables.

*That was our first thought, so we went through the child tables to check
but apparently we missed some. (please see below for the difference in the
explain analyze output)*

> Are any of the foreign keys multi-column?

*No, foreign keys are single column though some of the indexes (that we
presume are being used?) are multi-column, with the foreign key column
being the first field in the index.*

*I.e.CREATE INDEX message_transaction_state_idx ON log.message_tbl USING
btree (txnid, stateid);*
*where "txnid" is the foreign key column that references the TopTable.*

If so you probably
> need a matching multi-column index, not just indexes on the individual
> referencing columns.
>
> > How do we track down the cause of the poorly performing delete query?
>
> EXPLAIN ANALYZE on a DELETE, for starters. That would isolate whether
> it's the DELETE itself or one of the foreign-key updates, and if the
> latter which one. It's a little bit difficult to see the exact plan being
> used for a foreign-key update query, but I think one way you could do it
> is to enable auto_explain with auto_explain.log_nested_statements turned
> on.
>

*Output from EXPLAIN ANALYZE before additional indexes were added*

*"Delete on transaction_tbl (cost=0.00..10.89 rows=1 width=6) (actual
time=0.086..0.086 rows=0 loops=1)"" -> Index Scan using transaction_pk on
transaction_tbl (cost=0.00..10.89 rows=1 width=6) (actual
time=0.012..0.013 rows=1 loops=1)"" Index Cond: (id =
4614717)""Trigger for constraint address2transaction_fk on transaction_tbl:
time=0.460 calls=1""Trigger for constraint certificate2transaction_fk on
transaction_tbl: time=0.470 calls=1""Trigger for constraint msg2txn_fk on
transaction_tbl: time=0.433 calls=1""Trigger for constraint
note2transaction_fk on transaction_tbl: time=0.808 calls=1""Trigger for
constraint order2transaction_fk on transaction_tbl: time=0.535
calls=1""Trigger for constraint order2transaction_fk on transaction_tbl:
time=0.222 calls=1""Trigger for constraint certificate2order_fk on
order_tbl: time=1827.944 calls=1""Total runtime: 1830.995 ms"*

*Output from EXPLAIN ANALYZE after additional indexes were added*

*"Delete on transaction_tbl (cost=0.00..10.89 rows=1 width=6) (actual
time=0.070..0.070 rows=0 loops=1)"" -> Index Scan using transaction_pk on
transaction_tbl (cost=0.00..10.89 rows=1 width=6) (actual
time=0.022..0.023 rows=1 loops=1)"" Index Cond: (id =
4614669)""Trigger for constraint address2transaction_fk on transaction_tbl:
time=0.113 calls=1""Trigger for constraint certificate2transaction_fk on
transaction_tbl: time=0.424 calls=1""Trigger for constraint msg2txn_fk on
transaction_tbl: time=2.614 calls=1""Trigger for constraint
note2transaction_fk on transaction_tbl: time=0.350 calls=1""Trigger for
constraint order2transaction_fk on transaction_tbl: time=0.231
calls=1""Trigger for constraint order2transaction_fk on transaction_tbl:
time=0.088 calls=1""Trigger for constraint certificate2order_fk on
order_tbl: time=0.165 calls=1""Total runtime: 4.097 ms"*

Why is "order2transaction_fk" being triggered twice? Is that because
there're two affected rows?

>
> regards, tom lane
>

--
JONATAN EVALD BUUS

CTO

Mobile US +1 (305) 331-5242
Mobile DK +45 2888 2861
Telephone +1 (305) 777-0392
Fax. +1 (305) 777-0449
jonatan(dot)buus(at)cellpointmobile(dot)com
www.cellpointmobile.com

CellPoint Mobile Inc.
4000 Ponce de Leon Boulevard
Suite 470
Coral Gables, FL 33146
USA

'Mobilizing the Enterprise'