Skip to Main Content

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Mardy.

Asked: May 17, 2016 - 8:53 pm UTC

Last updated: July 30, 2020 - 12:33 am UTC

Version: Oracle 11g

Viewed 1000+ times

You Asked

I'm trouble-shooting a very slow running delete statement in a stored procedure. The delete statement attempts to delete one record from 1 table. The record to be deleted contains a key field that is pervasive throughout the database. Call it Order_Header. Sixteen tables in the database have foreign keys containing cascade delete constraints referencing Order_Header (children tables). The database also contains 11 tables with foreign keys containing cascade delete constraints referencing the children tables (grand children). I had a similar situation with another large cascade delete that was resolved by adding indexes to the foreign keys. The only potential issue that I see in this case is that two of the grandchildren are also children of Order_Header. Stated a little differently, two of the children of Order_Header are also grandchildren of other children of Order_Header. Could this be the cause of the slow performing delete?

and we said...

Best way is to trace it - 'delete cascade' is just a normal delete operation which you'll see in the trace file, eg

SQL> create table t1 ( p int primary key, d char(100));

Table created.

SQL> create table t2 ( p int primary key, d char(100), t1p int references t1 ( p ) on delete cascade);

Table created.

SQL> create table t3 ( p int primary key, d char(100), t2p int references t2 ( p ) on delete cascade);

Table created.

SQL> create table t4 ( p int primary key, d char(100), t3p int references t3 ( p ) on delete cascade);

Table created.

SQL>
SQL> insert into t1 values (1,'x');

1 row created.

SQL> insert into t2 values (1,'x',1);

1 row created.

SQL> insert into t3 values (1,'x',1);

1 row created.

SQL> insert into t4 values (1,'x',1);

1 row created.

SQL> delete from t1;


and the trace file shows the 'hidden' deletes as well

SQL ID: 8gvp49tr474f2 Plan Hash: 1208020946

delete from t1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          2          0           0
Execute      1      0.00       0.00          0          4         12           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          6         12           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 102  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  T1 (cr=43 pr=0 pw=0 time=16413 us)
         1          1          1   INDEX FAST FULL SCAN SYS_C0019864 (cr=4 pr=0 pw=0 time=49 us cost=2 size=13 card=1)(object id 146133)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

SQL ID: 76tmmyf7g40xm Plan Hash: 1451993194

delete from "MCDONAC"."T2" 
where
 "T1P" = :1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.00          0          7         10           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.00          0          7         10           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  T2 (cr=33 pr=0 pw=0 time=10327 us)
         1          1          1   TABLE ACCESS FULL T2 (cr=7 pr=0 pw=0 time=76 us)

********************************************************************************

SQL ID: 20wpmkwvwrzw1 Plan Hash: 3886669427

delete from "MCDONAC"."T3" 
where
 "T2P" = :1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          3          0           0
Execute      1      0.00       0.00          0          4          8           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          7          8           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  T3 (cr=20 pr=0 pw=0 time=4580 us)
         1          1          1   TABLE ACCESS FULL T3 (cr=7 pr=0 pw=0 time=91 us)

********************************************************************************

SQL ID: 69c9c3ycwj33t Plan Hash: 1581231216

delete from "MCDONAC"."T4" 
where
 "T3P" = :1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          3          0           0
Execute      1      0.00       0.00          0          4          4           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          7          4           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 3)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  T4 (cr=7 pr=0 pw=0 time=95 us)
         1          1          1   TABLE ACCESS FULL T4 (cr=7 pr=0 pw=0 time=37 us)

********************************************************************************




So that will tell you where the slow down is.

Rating

  (1 rating)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Same situation on cascade no action

Roman, July 29, 2020 - 6:55 am UTC

Hi TOM! Thank you for a great example!
I have pretty the same situation but I have FK with no action option so I can't see any operations in my trace connected to checking on FK but my delete takes very long time. Could you please advice something to track time-leaks down? Any kind of traces or something.
Here's what I have in my trace.

SQL ID: 71vbsharan1f1 Plan Hash: 663052182

delete /*+ parallel(1) */  from DOCUMENTS s 
where
s.id IN (:c_id)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      6    264.88     460.49       2591     140034  245669840        6000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7    264.88     460.49       2591     140034  245669840        6000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 23     (recursive depth: 3)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      2539        0.01          2.06
  library cache: mutex X                        555        0.01          0.56
  log file switch completion                      3        0.05          0.11
  latch: cache buffers chains                     9        0.00          0.00
  buffer busy waits                            2373        0.00          0.02
  buffer deadlock                                 8        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
********************************************************************************



Connor McDonald
July 30, 2020 - 12:33 am UTC

Even with no action (I assume you are talking about on-delete-cascade), we still have nearly just as much work to do, because for every row you delete, we must check the child table to see if any data exists.

Do you have a FK index in place ?