Обсуждение: Poor performance for delete query
Greetings,
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.
"id" is the primary key in TopTable, and will trigger deletes of a few associated rows in child tables using foreign keys with ON DELETE CASCADE as outlined below: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.
TopTable
--- Table 1 (references TopTable): 11.811.200 rows (rows deleted)--- Table 3 (references TopTable): 8.227.700 rows (now rows deleted)
--- Table 4 (references table 3): 4.294.140 rows (now rows deleted)
--- Table 5 (references table 3): 4.154.850 rows (now rows deleted)
--- Table 6 (references table 5): 5.185.450 rows (now rows deleted)
--- Table 7 (references table 3): 68.206 rows (now rows deleted)--- Table 5 (references table 3): 4.154.850 rows (now rows deleted)
--- Table 6 (references table 5): 5.185.450 rows (now rows deleted)
--- Table 8 (references table 3): 108 rows (now rows deleted)
--- Table 9 (references TopTable): 2448 rows (now rows deleted)
Indexes have been defined for all columns referenced by the foreign key in each of the tables.
Hardware / Software info
Database: PostgreSQL 9.2.2 64-bit
OS: Red Hat Enterprise Linux Server release 5.5
CPU: 8 core Intel Xeon 2.3GHz
RAM: 16GB
RAM: 16GB
Disk: IBM SAN
How do we track down the cause of the poorly performing delete query?
How do we track down the cause of the poorly performing delete query?
Many thanks for your advice
/Jona
Jonatan Evald Buus <jonatan.buus@cellpointmobile.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. Are any of the foreign keys multi-column? 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.
regards, tom lane
Many thanks for the swift reply Tom, please see additional input below
/JonaOn 24 April 2014 22:29, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Jonatan Evald Buus <jonatan.buus@cellpointmobile.com> writes:I'd really have to bet that you forgot to index one of the referencing
> 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.
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);
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.EXPLAIN ANALYZE on a DELETE, for starters. That would isolate whether
> How do we track down the cause of the poorly performing delete query?
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"
" -> 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.buus@cellpointmobile.com
www.cellpointmobile.com
CellPoint Mobile Inc.
4000 Ponce de Leon Boulevard
Suite 470
Coral Gables, FL 33146
USA
'Mobilizing the Enterprise'
Jonatan Evald Buus <jonatan.buus@cellpointmobile.com> writes:
> On 24 April 2014 22:29, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> 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)*
I'm confused. Your second EXPLAIN ANALYZE looks like you fixed the
problem. Are you still thinking there's an issue?
> Why is "order2transaction_fk" being triggered twice? Is that because
> there're two affected rows?
No, I'd have expected a delete of multiple rows to show as calls=N,
not N separate entries.
Maybe there are recursive queries buried under here somewhere?
That is, are you expecting any of the cascaded deletes to cascade further?
I don't recall exactly what EXPLAIN is likely to do with such cases.
regards, tom lane
On 24 April 2014 23:25, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Deleting from the TopTable (Transaction), I'd expect the following effects:
Jonatan Evald Buus <jonatan.buus@cellpointmobile.com> writes:
> On 24 April 2014 22:29, Tom Lane <tgl@sss.pgh.pa.us> wrote:>> I'd really have to bet that you forgot to index one of the referencing> *That was our first thought, so we went through the child tables to check
>> tables.> but apparently we missed some. (please see below for the difference in the> explain analyze output)*
I'm confused. Your second EXPLAIN ANALYZE looks like you fixed the
problem. Are you still thinking there's an issue?
I believe we improved it at least, whether it's permanently fixed remaines to be seen once transaction volume increases again.
No, I'd have expected a delete of multiple rows to show as calls=N,
> Why is "order2transaction_fk" being triggered twice? Is that because
> there're two affected rows?
not N separate entries.
Maybe there are recursive queries buried under here somewhere?
That is, are you expecting any of the cascaded deletes to cascade further?
I don't recall exactly what EXPLAIN is likely to do with such cases.
Deleting from the TopTable (Transaction), I'd expect the following effects:
- 0 affected rows in Address using address2transaction_fk
- 0 affected rows in Certificate using certificate2transaction_fk
- 0 affected rows in Note using note2transaction_fk
- 0 affected rows in Certificate using certificate2transaction_fk
- 0 affected rows in Note using note2transaction_fk
- 1 - N affected rows in Order using order2transaction_fk
A deletion in "Order" would also trigger an ON DELETE CASCADE to Certificate using certificate2order_fk, which affects 0 rows.
This doesn't explain the extra trigger of "order2transaction_fk".
Any guidelines as to how we may investigate this further would be greatly appreciated.
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.buus@cellpointmobile.com
www.cellpointmobile.com
CellPoint Mobile Inc.
4000 Ponce de Leon Boulevard
Suite 470
Coral Gables, FL 33146
USA
'Mobilizing the Enterprise'
Jonatan Evald Buus <jonatan.buus@cellpointmobile.com> writes:
> On 24 April 2014 23:25, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Jonatan Evald Buus <jonatan.buus@cellpointmobile.com> writes:
>>> Why is "order2transaction_fk" being triggered twice? Is that because
>>> there're two affected rows?
>> No, I'd have expected a delete of multiple rows to show as calls=N,
>> not N separate entries.
> This doesn't explain the extra trigger of "order2transaction_fk".
> Any guidelines as to how we may investigate this further would be greatly
> appreciated.
If you could show us your exact database schema, it might become
clearer what's happening. I'm wondering about duplicate constraint names
for instance ...
regards, tom lane