Best practice to delete rows with a CLOB column

4101461

Environment: Oracle 12.1.0.2 on Exadata

I have a table with 30 columns, one of which is a CLOB, that contains about 26 million rows.

I have a purge job (PL/SQL packaged procedure) that DELETEs rows from nine (9) other tables based on a list of IDs from the driver table that contains the CLOB.

I save the list of IDs in a global temporary table and use that to delete the associated rows from the other tables that are done in the correct order to maintain all the FK relationships.

I am running a test today that has identified about 98,000 IDs to be purged but I have about 5 million that need to be purged to 'catch up' and going forward I'll have about 10,000 per day to purge.

The DELETE on the other 9 tables runs very quickly.

The table with the CLOB column is taking many times longer than the others, like several hours as opposed to several minutes.

I'm guessing there is a better and more efficient way to remove the rows from the table containing the CLOB and to regain the storage used by the deleted CLOB.

I'm currently issuing just a 'DELETE FROM <table> WHERE ID IN (SELECT ID FROM <gtt>', where ID is the PK.

I would appreciate any suggestions and order of operational steps to accomplish this purge, both for the 'catch up' and the daily run of 10,000.

Thanks in advance for all the help!!   Much appreciated!

-gary

Jonathan Lewis

Gary,

You said the foreign keys were indexed, but if you check the index definitions the claimid keeps appearing as the SECOND column in the index. The index is only valid to avoid the foreign key locking and explicit query if it starts with the foreign key.

In the output from your trace file we see the following queries:

select /*+ all_rows */ count(1) from "EDI_MSTR"."CLAIMADJUSTMENTS" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."CLAIMFILINGS" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."EXTERNALCAUSEOFINJURIES" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."HCPCS" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."IDCPROCEDURECODES" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."OTHERDIAGNOSISCODES" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."REASONSFORVISIT" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."REQUESTCLAIMS" where "CLAIMID" = :1

select /*+ all_rows */ count(1) from "EDI_MSTR"."VALUECODES" where "CLAIMID" = :1

Some are executed as index fast full scans, some are index skip scans.

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        0          0          0  DELETE  CLAIMS (cr=141431825 pr=153889 pw=0 time=918574651 us)

      2529      2529      2529  TABLE ACCESS BY INDEX ROWID BATCHED CLAIMS (cr=88772 pr=87780 pw=0 time=1210753 us cost=20424 size=19154 card=157)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=22 pr=15 pw=0 time=9707 us)

        0          0          0  INDEX SKIP SCAN CLAIMADJUST_CODEID_CLAIMID_NU1 (cr=22 pr=15 pw=0 time=9697 us cost=8 size=36 card=6)(object id 89633)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=64 pr=0 pw=0 time=834 us)

        0          0          0  INDEX SKIP SCAN CLAIMFILINGS_CODEID_CLAIMID_NU (cr=64 pr=0 pw=0 time=831 us cost=25 size=6 card=1)(object id 89638)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=1279 pr=1230 pw=0 time=44570 us)

        0          0          0  INDEX STORAGE FAST FULL SCAN EXTERNALCAUSEOFINJ_CODE_NU1 (cr=1279 pr=1230 pw=0 time=44564 us cost=294 size=12 card=2)(object id 89643)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=12634 pr=11231 pw=0 time=3555409 us)

        0          0          0  INDEX SKIP SCAN HCPCS_CODE_CLAIMID_NU1 (cr=12634 pr=11231 pw=0 time=3555404 us cost=13729 size=18 card=3)(object id 89644)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=1149 pr=1107 pw=0 time=40681 us)

        0          0          0  INDEX STORAGE FAST FULL SCAN IDCPROCCODES_CODE_CLAIMID_NU1 (cr=1149 pr=1107 pw=0 time=40673 us cost=282 size=18 card=3)(object id 89646)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=24993 pr=22355 pw=0 time=6939411 us)

        0          0          0  INDEX SKIP SCAN OTHERDIAGCODE_CODE_CLAIMID_NU1 (cr=24993 pr=22355 pw=0 time=6939403 us cost=39435 size=18 card=3)(object id 89647)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=17498 pr=16945 pw=0 time=516021 us)

        0          0          0  INDEX STORAGE FAST FULL SCAN REASONSFORVIS_CODE_CLAIMID_NU1 (cr=17498 pr=16945 pw=0 time=516014 us cost=4088 size=6 card=1)(object id 89648)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=5 pr=4 pw=0 time=1534 us)

        0          0          0  INDEX SKIP SCAN REQUESTCLAIMS_RESP_CLAIMID_NU1 (cr=5 pr=4 pw=0 time=1530 us cost=2 size=6 card=1)(object id 89650)

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

        1          1          1  SORT AGGREGATE (cr=118 pr=107 pw=0 time=33258 us)

        0          0          0  INDEX SKIP SCAN VALUECODES_CODE_CLAIMID_NU1 (cr=118 pr=107 pw=0 time=33254 us cost=100 size=6 card=1)(object id 89661)

In the execution plan the figures for cr=, pr=, and time= are just for the first captured execution,  (cr = consistent reads, pr = physical reads)

To minimise the workload while keeping the foreign key constraints enabled you need to have indexes that start with claimid (which may mean you could simply re-arrange the order of the indexes you currently have - it depends how effective the indexes are for the queries you currently run.)

Regards

Jonathan Lewis

Mike Kutz

At 20%, ( 5M to delete / 26M rows), it is usually better to create a table with the data you want to keep and swap tables.

Even at 10k/day, it may make sense to PARTITION the table appropriately (if you are on EE and have licensed the Partition Add-on)

Also, check for FKs to the table with the CLOBs. (and Triggers)

MK

Paulzip

Was does the explain plan show?  Any FKs linking to the table?  If so, are they indexed?

Are the GTT stats stale?  In which case it might not know to use the PK index.

There are lots of gotchas with LOBs if you don't set them up correctly.  I would run an AWR report whilst you do these deletes.

Jonathan Lewis wrote an excellent set of articles regarding LOBs and various issues associated with their use - especially Basic Lobs.  Take a read here and here if you aren't using secure lobs.

4101461

Thanks very much for the feedback.

I am a bit handcuffed due to not having access to all the tools like AWR, ASH, tkprof, trace files, etc.

Partitioning is not an option.

The application is kind of a pass-through in that the data is received, reviewed by some users and then passed on to a mainframe application.

The LOB is a SECUREFILE as seen on the below table definition.  There is no maintenance on the LOB data, it is just passed through and is in the format of an EDI file.

LOB (RAWDATA) STORE AS SECUREFILE (  TABLESPACE  EDIE_DATA  ENABLE      STORAGE IN ROW  CHUNK       8192  NOCACHE  LOGGING      STORAGE    (                  INITIAL          104K                  NEXT             1M                  MINEXTENTS       1                  MAXEXTENTS       UNLIMITED                  PCTINCREASE      0                  BUFFER_POOL      DEFAULT                 ))

I just deleted about 9,000 rows and it took 2 hours and 15 minutes.

This purge job runs daily and in some cases has to purge 100,000 rows so you see the urgency in finding a better way.

The table has several FKs and the PK on the table is used in several other FKs.  All FKs are indexed.

OEM  showed a reasonable Explain Plan in that the expected indexes were used and the row counts were accurate.  The run graph showed, what I thought, was a very high CPU usage (90+%) during the delete operation.

I did read the articles from Jonathan Lewis but they were focused on BASICFILE LOBs and issues with heavy maintenance on the LOBs themselves.  I don't have that issue here.

Any other thoughts are most welcome.

Thanks again!!

-gary

4101461

I guess my basic question is why would a table with a CLOB column take so much longer to delete rows from that a table without one?

Is there something about the LOB Index that I need to investigate?  I haven't found much documentation on LOB indexes so far.

I tried setting the CLOB column to NULL and then deleting the rows but the duration was the same and still very much longer than tables without the CLOB column.

I was able to watch the process in OEM and saw lots of CPU usage and looking at V$SESSTAT and V$SESSION_EVENT I saw lots of I/O.

Any ideas/suggestions are most welcome.

-gary

Tubby

You say you don't have access to AWR or TKPROF, and why is that? Seems like if you have an issue you need sorted you'd be able to get those somehow, no?

That aside, your version does support parallel dml so you could give that a try though this could just make things worse for you

https://oracle-base.com/articles/12c/securefiles-enhancements-12c

"

Parallel DML (PDML) Support Enhancements

"

Cheers,

4101461

I guess my real question is why does it take so much longer to DELETE rows from a table with a CLOB column than it does from a table without one?

The non-CLOB tables have many more rows but take just minutes to delete the tagged rows.

There doesn't seem to be much I can do the the LOB index and I've already tried to set the CLOB to NULL and then do the delete but it didn't help the run time.

Any suggestions are welcome.

-gary

Jonathan Lewis

If you can't take advantage of the AWR or trace/tkprof features could you start with a simple queries against v$mystat and v$session_event for your session (i.e. connect to SQL*Plus, delete a small batch of ids, then query the v$ views) or do you have absolutely no access to anything that allows you to see what work the database is doing.

My first thoughts are

1) there's a foreign key that you've overlooked and it's not indexed, so Oracle is doing a tablescan of some other table for every row you delete in the CLOB table.

2) assuming all the foreign key tables are indexed, perhaps after your delete of all the child rows Oracle has to do a lot of delayed block cleanout for each row that it deletes from the parent table as it checks the child indexes.

3) Is there are compression involved on the table segment

4) Is the time spent processing the LOB segment, or is it about the table segment and its indexes?

5) Can we associate the problem with the NOCACHE declaration, or with the LOGGING declaration.

6) (ADDED LATER): is there a concurrency issue with other users inserting new CLOBs or updating existing ones.

Basic test

Connect to SQL*Plus

Delete a small batch

-- set formatting for tidy output.

select from v$mystat joined to v$statname to report the statistics (where value != 0)

select from v$session_event where sid = {your session's SID}

Examine results for clues.

Regards

Jonathan Lewis

4101461

Hi Jonanthan

Thanks for jumping in here.  I was able to capture some data from V$SESSION_EVENT and V$SESSTAT as seen below.

I am the only user in this database. 

All FKs reference PKs on the parent tables and indexes exist.

I'm not sure how to check for the delayed block cleanout.

No compression on the table as seen in the CREATE script.

Environment is Oracle 12.1.0.2 on Exadata.

The largest LOB length is 100245.

CREATE TABLE <table>(  ID                         NUMBER,  .  IMPORTDATE                 DATE               NOT NULL,  RAWDATA                    CLOB, . . . . .)LOB (RAWDATA) STORE AS SECUREFILE (  TABLESPACE  EDIE_DATA  ENABLE      STORAGE IN ROW  CHUNK       8192  NOCACHE  LOGGING      STORAGE    (                  INITIAL          104K                  NEXT             1M                  MINEXTENTS       1                  MAXEXTENTS       UNLIMITED                  PCTINCREASE      0                  BUFFER_POOL      DEFAULT                 ))TABLESPACE EDIE_DATAPCTUSED    0PCTFREE    10INITRANS   1MAXTRANS   255STORAGE    (            INITIAL          64K            NEXT             1M            MINEXTENTS       1            MAXEXTENTS       UNLIMITED            PCTINCREASE      0            BUFFER_POOL      DEFAULT           )LOGGING ROW STORE COMPRESS ADVANCEDNOCACHEMONITORINGENABLE ROW MOVEMENT;

SQL> select * from v$session_event where sid = 678;       SID EVENT                               TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS          CON_ID---------- ----------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------- ----------       678 Disk file operations I/O                     74              0           0            0          0              1493  166678035    1740759767           8 User I/O                33       678 Disk file Mirror Read                         2              0           0          .03          0               567   13102552    1740759767           8 User I/O                33       678 control file sequential read                  7              0           0          .02          0              1668 3213517201    4108307767           9 System I/O              33       678 latch: cache buffers chains                  17              0           0            0          0               265 2779959231    3875070507           4 Concurrency             33       678 log file sync                                 5              0           1           .1          0              5177 1328744198    3386400367           5 Commit                  33       678 latch: shared pool                           17              0           0          .01          0              2310 2696347763    3875070507           4 Concurrency             33       678 resmgr:cpu quantum                           64              0          88         1.37         29            879799 1452455426    2396326234          10 Scheduler               33       678 PX Deq: Join ACK                            396              0           2          .01          0             20849 4205438796    2723168908           6 Idle                    33       678 PX Deq: Parse Reply                         198              0           1          .01          0             10475 4255662421    2723168908           6 Idle                    33       678 PX Deq: Execute Reply                       708              0           9          .01          3             85317 2599037852    2723168908           6 Idle                    33       678 PX Deq: Table Q Normal                       94              0           0            0          0               204  799271425    2723168908           6 Idle                    33       678 SQL*Net message to client                   124              0           0            0          0               336 2067390145    2000153315           7 Network                 33       678 SQL*Net more data to client                  10              0          15         1.53         15            152684  554161347    2000153315           7 Network                 33       678 SQL*Net message from client                 123              0      687196      5586.96     224298        6871964897 1421975091    2723168908           6 Idle                    33       678 SQL*Net break/reset to client                 8              0          21         2.66          6            213085 1963888671    4217450380           1 Application             33       678 cell single block physical read          105284              0        3042          .03          2          30419630 2614864156    1740759767           8 User I/O                33       678 cell multiblock physical read             80296              0        4435          .06          2          44345672  443865681    1740759767           8 User I/O                33       678 cell list of blocks physical read         13025              0        2602           .2          1          26017880 3975960017    1740759767           8 User I/O                33       678 events in waitclass Other                   427              3           1            0          0              5090 1736664284    1893977003           0 Other                   33

SQL> select ss.value, sn.name from v$sesstat ss, v$statname sn where ss.statistic# = sn.statistic# and sid = 678 and value != 0 order by value;               VALUE NAME-------------------- ----------------------------------------------------------------                   1 shared hash latch upgrades - wait                   1 commit cleanouts successfully completed                   1 user commits                   1 logons cumulative                   1 Heap Segment Array Updates                   1 deferred (CURRENT) block cleanout applications                   1 user logons cumulative                   1 redo synch time                   1 logons current                   1 min active SCN optimization applied on CR                   2 commit batch/immediate performed                   2 commit immediate performed                   2 pinned cursors current                   2 user rollbacks                   2 commit batch/immediate requested                   2 commit immediate requested                   2 transaction rollbacks                   4 redo synch writes                   4 redo write info find                   4 parse count (failures)                   4 redo synch time overhead count (  2ms)                   4 sql area evicted                   4 sql area purged                   5 calls to kcmgas                   5 opened cursors current                   5 Batched IO buffer defrag count                  11 immediate (CURRENT) block cleanout applications                  11 Block Cleanout Optim referenced                  14 Parallel operations not downgraded                  14 DFO trees parallelized                  14 queries parallelized                  15 change write time                  21 application wait time                  26 cursor authentications                  26 enqueue waits                  29 CCursor + sql area evicted                  44 table scans (short tables)                  91 scheduler wait time                  99 commit cleanout failures: callback failure                 100 commit cleanouts                 121 Requests to/from client                 121 workarea executions - optimal                 122 SQL*Net roundtrips to/from client                 140 heap block compress                 215 session cursor cache count                 215 Batched IO double miss count                 228 sorts (memory)                 256 cluster key scans                 263 parse count (hard)                 316 parse time cpu                 401 index fetch by key                 413 cluster key scan block gets                 582 parse time elapsed                 611 redo synch time overhead (usec)                 646 messages sent                 746 cleanout - number of ktugct calls                 746 commit txn count during cleanout                 746 cleanouts only - consistent read gets                 746 immediate (CR) block cleanout applications                 781 redo subscn max counts                 818 physical reads for flashback new                 863 parse count (total)                 901 table scan blocks gotten                 950 user calls                 979 switch current to new buffer               1,048 index scans kdiixs1               1,162 pinned buffers inspected               2,562 PX local messages sent               2,562 PX local messages recv'd               3,836 enqueue releases               4,052 enqueue requests               4,332 sorts (rows)               5,000 HSC Compressed Segment Block Changes               5,001 HSC Heap Segment Block Changes               5,276 redo synch time (usec)               5,396 Batched IO single block count               9,001 index fast full scans (full)              10,000 rollback changes - undo records applied              10,085 user I/O wait time              10,217 non-idle wait time              10,728 table fetch continued row              11,924 Batched IO (full) vector count              26,174 physical read total multi block requests              27,537 session cursor cache hits              28,145 opened cursors cumulative              28,263 execute count              28,637 redo entries              30,158 bytes received via SQL*Net from client              31,890 recursive calls              53,422 enqueue conversions              56,473 db block changes              66,042 hot buffers moved to head of LRU              66,650 table scan disk non-IMC rows gotten              76,583 dirty buffers inspected              78,120 table scan rows gotten              86,599 Batched IO (bound) vector count              93,141 Batched IO vector read count             115,464 bytes sent via SQL*Net to client             127,499 rows fetched via callback             129,760 consistent gets examination (fastpath)             129,827 consistent gets examination             150,758 calls to kcmgcs             278,114 recursive cpu usage             285,916 CPU used when call started             285,978 CPU used by this session             344,739 db block gets from cache (fastpath)             398,951 non-idle wait count             402,836 db block gets from cache             402,836 db block gets           1,091,766 physical read IO requests           1,091,773 cell flash cache read hits           1,091,773 physical read requests optimized           1,091,773 physical read total IO requests           1,111,097 in call idle wait time           1,355,344 session uga memory           1,404,664 DB time           1,615,516 shared hash latch upgrades - no wait           2,753,959 Batched IO same unit count           2,820,029 physical reads cache prefetch           2,893,454 Batched IO vector block count           3,018,722 physical reads           3,018,722 physical reads cache           3,019,701 free buffer requested           3,362,440 session pga memory           4,116,156 free buffer inspected           5,640,894 Batched IO block miss count           5,806,224 undo change vector size           6,938,816 session uga memory max           8,594,990 buffer is pinned count          11,135,992 redo size          11,904,146 table fetch by rowid          15,226,484 buffer is not pinned count          17,190,536 session pga memory max          23,656,667 calls to get snapshot scn: kcmgss         100,790,062 file io wait time         131,490,867 no work - consistent read gets         131,777,876 consistent gets pin (fastpath)         131,975,535 consistent gets pin         132,105,362 consistent gets         132,105,362 consistent gets from cache         132,508,198 session logical reads       1,596,722,183 session connect time       1,596,722,183 process last non-idle time      24,729,370,624 physical read bytes      24,729,485,312 cell physical IO interconnect bytes      24,729,485,312 physical read total bytes optimized      24,729,485,312 physical read total bytes   1,085,507,158,016 logical read bytes from cache

SQL> select constraint_name, table_name, r_constraint_name, status, index_name from user_constraints where constraint_type = 'R' order by 2;CONSTRAINT_NAME                TABLE_NAME                     R_CONSTRAINT_NAME              STATUS   INDEX_NAME------------------------------ ------------------------------ ------------------------------ -------- ------------------------------CLAIMADJUSTMENTS_CLAIMID_FK    CLAIMADJUSTMENTS               CLAIMS_PK                      ENABLEDCLMADJSTMNTS_CLAIMREASONID_FK  CLAIMADJUSTMENTS               CLAIMREASONS_PK                ENABLEDCLAIMFILINGS_CLAIMID_FK        CLAIMFILINGS                   CLAIMS_PK                      ENABLEDCLAIMFILNGS_CLAIMFILINDCDID_FK CLAIMFILINGS                   CLAIMFILINGINDICATORCODES_PK   ENABLEDCLAIMS_STATEID_FK              CLAIMS                         STATES_PK                      ENABLEDCLAIMS_SOURCETYPEID_FK         CLAIMS                         SYSTEMTYPES_PK                 ENABLEDCLAIMS_CLAIMTYPEID_FK          CLAIMS                         SYSTEMTYPES_PK                 ENABLEDEXTRNLCAUSEINJURIES_CLAIMID_FK EXTERNALCAUSEOFINJURIES        CLAIMS_PK                      ENABLEDHCPCS_CLAIMID_FK               HCPCS                          CLAIMS_PK                      ENABLEDHCPCS_PARENTID_FK              HCPCS                          HCPCS_PK                       ENABLEDIDCPROCEDURECODES_CLAIMID_FK   IDCPROCEDURECODES              CLAIMS_PK                      ENABLEDOTHERDIAGNOSISCODES_CLAIMID_FK OTHERDIAGNOSISCODES            CLAIMS_PK                      ENABLEDREASONSFORVISIT_CLAIMID_FK     REASONSFORVISIT                CLAIMS_PK                      ENABLEDREQUESTCLAIMS_CLAIMID_FK       REQUESTCLAIMS                  CLAIMS_PK                      ENABLEDREQUESTCLAIMS_STATUSID_FK      REQUESTCLAIMS                  SYSTEMTYPES_PK                 ENABLEDREQUESTCLAIMS_REQUESTID_FK     REQUESTCLAIMS                  REQUESTS_PK                    ENABLEDREQUESTS_USERID_FK             REQUESTS                       USERS_PK                       ENABLEDREQUESTS_TYPEID_FK             REQUESTS                       SYSTEMTYPES_PK                 ENABLEDREQUESTS_STATUSID_FK           REQUESTS                       SYSTEMTYPES_PK                 ENABLEDSUBSCRIBERS_CLAIMID_FK         SUBSCRIBERS                    CLAIMS_PK                      ENABLEDSUBSCRBRS_PYRESPONSTYPEID_FK   SUBSCRIBERS                    SYSTEMTYPES_PK                 ENABLEDVALUECODES_CLAIMID_FK          VALUECODES                     CLAIMS_PK                      ENABLED

Thanks very much for any suggestions.

-gary

Jonathan Lewis

How many rows should this have deleted from the CLOB table ?

Was it deleting ONLY from the CLOB table ?

Given the exercise you thought you'd done is it reasonable for Oracle to report 11,900,000 "table fetch by rowid" ? Given the most of your time was spent on physical read requests that number would tend to explan why there was a lot of time spent on the delete. (Even when almost all the reads were from the smart flash cache).

What were the rollbacks ? You had 2 "user rollbacks" which were also "transaction rollbacks" which between them applied exactly 10,000 "rollback changes - undo records applied"?

Can you explain why your stats show 28,000 executions.

Are any of the other tables declared as "row store compress advanced" ?

What's your setting for db_file_multiblock_read_count ?

For future reference, don't sort the session statistics by value - just don't sort them at all if they're for a single session, there's a default pattern that will appear that is usually repeatable across tests; sorting by value means statistics move randomly around the page and make it hard to find the useful information.

Regards

Jonathan Lewis

4101461

Jonathan

I just ran a new clean test and captured the run stats.

I deleted 1170 rows that took 22 minutes.

I am the only one in the database.

The delete was only from one(1) table that has the one (1) CLOB column where the maximum length of the CLOB column is 3073 bytes in the set of rows being deleted.

Data from V$SESSION_EVENT and V$SESSTAT were gathered after the DELETE operation had completed.

NAME                                 TYPE        VALUE------------------------------------ ----------- ------------------------------db_file_multiblock_read_count        integer     128

SQL> select * from v$session_event where sid = 2689;       SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS                    CON_ID---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- ------------------------- ----------      2689 Disk file operations I/O                          20              0           0            0          0               324  166678035    1740759767           8 User I/O                          33      2689 log file sync                                      1              0           0          .01          0                98 1328744198    3386400367           5 Commit                            33      2689 resmgr:cpu quantum                                18              0          18            1          3            179843 1452455426    2396326234          10 Scheduler                         33      2689 SQL*Net message to client                         19              0           0            0          0                55 2067390145    2000153315           7 Network                           33      2689 SQL*Net message from client                       18              0       18596      1033.13      18191         185962916 1421975091    2723168908           6 Idle                              33      2689 cell single block physical read                42590              0        1276          .03          3          12764409 2614864156    1740759767           8 User I/O                          33      2689 cell multiblock physical read                    201              0          27          .14          1            273031  443865681    1740759767           8 User I/O                          337 rows selected.SQL> select ss.value, sn.name from v$sesstat ss, v$statname sn where ss.statistic# = sn.statistic# and sid = 2689 and value != 0;     VALUE NAME---------- ----------------------------------------------------------------        18 Requests to/from client         1 logons cumulative         1 logons current     10894 opened cursors cumulative         4 opened cursors current        26 user calls     11399 recursive calls    129286 recursive cpu usage         1 pinned cursors current         1 user logons cumulative  56247801 session logical reads    129393 CPU used when call started    129393 CPU used by this session    130640 DB time      1303 user I/O wait time        17 scheduler wait time      1321 non-idle wait time     85659 non-idle wait count1597071931 session connect time1597071931 process last non-idle time    715440 session uga memory   1464920 session uga memory max        11 messages sent   2707080 session pga memory   3362440 session pga memory max      3570 enqueue requests     22239 enqueue conversions      3552 enqueue releases     42791 physical read total IO requests       152 physical read total multi block requests     42791 physical read requests optimized 509517824 physical read total bytes optimized 509517824 physical read total bytes 509517824 cell physical IO interconnect bytes     46721 db block gets     46721 db block gets from cache     27530 db block gets from cache (fastpath)  56201080 consistent gets  56201080 consistent gets from cache  56199734 consistent gets pin  56157457 consistent gets pin (fastpath)      1346 consistent gets examination      1346 consistent gets examination (fastpath)4.6078E+11 logical read bytes from cache     62197 physical reads     62197 physical reads cache     42791 physical read IO requests 509517824 physical read bytes     15141 db block changes         1 consistent changes        10 change write time     62789 free buffer requested        11 dirty buffers inspected         6 pinned buffers inspected     53498 hot buffers moved to head of LRU     54347 free buffer inspected         1 commit cleanouts         1 commit cleanouts successfully completed         1 CR blocks created       591 switch current to new buffer     19406 physical reads cache prefetch     10579 shared hash latch upgrades - no wait       378 physical reads for flashback new     58564 calls to kcmgcs         2 calls to kcmgas     14465 calls to get snapshot scn: kcmgss      8679 redo entries   5255696 redo size      1690 redo subscn max counts       105 redo synch time (usec)        23 redo synch time overhead (usec)         1 redo synch time overhead count (  2ms)         1 redo synch writes         1 redo write info find  13037440 file io wait time   4088952 undo change vector size         1 data blocks consistent reads - undo records applied  56139565 no work - consistent read gets      1635 cleanouts only - consistent read gets         1 cleanouts and rollbacks - consistent read gets        35 immediate (CURRENT) block cleanout applications      1636 immediate (CR) block cleanout applications         1 deferred (CURRENT) block cleanout applications      1635 commit txn count during cleanout         1 active txn count during cleanout      1636 cleanout - number of ktugct calls        35 Block Cleanout Optim referenced        13 table scans (short tables)        31 table scan rows gotten        31 table scan disk non-IMC rows gotten        13 table scan blocks gotten      1412 table fetch by rowid         1 table fetch continued row       180 cluster key scans       307 cluster key scan block gets         7 rows fetched via callback      3510 index fast full scans (full)       210 index fetch by key       215 index scans kdiixs1      1171 HSC Compressed Segment Block Changes      1172 HSC Heap Segment Block Changes         1 Heap Segment Array Updates         8 sql area evicted     10847 session cursor cache hits        42 session cursor cache count        10 cursor authentications      1850 buffer is pinned count      1777 buffer is not pinned count        77 workarea executions - optimal         4 parse time cpu         5 parse time elapsed        74 parse count (total)        28 parse count (hard)     10892 execute count      6077 bytes sent via SQL*Net to client      5901 bytes received via SQL*Net from client        19 SQL*Net roundtrips to/from client       149 sorts (memory)      1499 sorts (rows)     42791 cell flash cache read hits

Thanks very much for your help!!!

-gary

Jonathan Lewis

I think your foreign key constraints are declared as "on delete cascade" - so for every row you delete from the CLOB table Oracle goes through an attempt to delete from the 9 children in turn before deleting from the parent, with calls like:

delete from "SCHEMA"."CHILD_TABLE"

where "PARENT_ID" = :1

In most cases this is probably doing an index range scan (only) of the "foreign key" indexes.

It's possible that in a couple of cases it's doing an index fast full scan of the "foreign key" indexes - which may explain the 56M consistent gets and huge CPU utilisation.

For your 1170 rows deleted you can see:

• 10892 execute count  -- that's close to 9 * 1170  delete statements plus a little sys-recursive stuff
• 22239 enqueue conversions -- that 19 * 1170:  each child table will result in an up-convert/down-convert.  (I'll have to think about the 19th).
• 3510 index fast full scans (full)  -- that's 3 * 1170, which looks 3 "delete" calls using an index fast full scan.

I'm now wondering if all the extra time is due to the three index fast full scans - it's a path that wasn't originally available for a delete but became available in 12.2 (so maybe you've got the patch, or maybe it actually became available in 12.1).  I've got a note about this, including a case where a client hit a massive performance problem because of the index fast full scan: https://jonathanlewis.wordpress.com/2014/06/19/delete-costs/ The solution in that case probably wouldn't be relevant in your case, unfortunately; but the first thing, anyway, is to confirm that that's where the time is going.

You need to enable sql_trace and run the delete, then apply tkprof to the resulting trace file, with the option "sort=exeqry"; this will bring the queries that do most consistent gets to the top of the output, and will identify which child tables are the ones to investigate.

Regards

Jonathan Lewis

UPDATE:  I just checked the fix_control list for 12.1.0.2 and there's this item in it:

17908541

QKSFM_ACCESS_PATH_17908541

consider index fast full scan on DELETE to non-IOT

So this means the delete using index fast full scan could happen with your platform.

If you want to do a quick and dirty test of the hypothesis you could set up a similar small delete and then:

alter session set "_fix_control"='17908541:0';

before starting the delete.

4101461

Jonathan

I did a ROLLBACK from the first session to reclaim my target rows for testing.

I started a new session and after setting the parameter as directed the DELETE still took about 20 minutes.

Here are the details:

SQL> alter session set "_fix_control"='17908541:0';Session altered.Elapsed: 00:00:00.11SQL> delete from claims where importdate < sysdate -445 and id > 150000;1170 rows deleted.Elapsed: 00:19:48.48SQL>

SQL> select ss.value, sn.name from v$sesstat ss, v$statname sn where ss.statistic# = sn.statistic# and sid = 1059 and value != 0;     VALUE NAME---------- ----------------------------------------------------------------        23 Requests to/from client         1 logons cumulative         1 logons current     10565 opened cursors cumulative         7 opened cursors current        33 user calls     10722 recursive calls    118524 recursive cpu usage         4 pinned cursors current         1 user logons cumulative  40335941 session logical reads    118602 CPU used when call started    118602 CPU used by this session    118840 DB time        10 user I/O wait time       136 scheduler wait time       146 non-idle wait time       476 non-idle wait count1597080681 session connect time1597080681 process last non-idle time    544696 session uga memory    544696 session uga memory max         1 messages sent   2248328 session pga memory   2838152 session pga memory max      3574 enqueue requests     22239 enqueue conversions      3556 enqueue releases       188 physical read total IO requests       188 physical read requests optimized   1540096 physical read total bytes optimized   1540096 physical read total bytes   1540096 cell physical IO interconnect bytes     46934 db block gets     46934 db block gets from cache     27977 db block gets from cache (fastpath)  40289007 consistent gets  40289007 consistent gets from cache  40288941 consistent gets pin  40288941 consistent gets pin (fastpath)        66 consistent gets examination        66 consistent gets examination (fastpath)3.3043E+11 logical read bytes from cache       188 physical reads       188 physical reads cache       188 physical read IO requests   1540096 physical read bytes     13453 db block changes         1 consistent changes         8 change write time       780 free buffer requested        35 hot buffers moved to head of LRU        52 free buffer inspected         1 commit cleanouts         1 commit cleanouts successfully completed         1 CR blocks created       591 switch current to new buffer         1 shared hash latch upgrades - no wait       188 physical reads for flashback new        58 calls to kcmgcs         2 calls to kcmgas     14142 calls to get snapshot scn: kcmgss      6992 redo entries   5118304 redo size        15 redo subscn max counts         1 redo synch writes    103309 file io wait time   4089104 undo change vector size         1 data blocks consistent reads - undo records applied  40288936 no work - consistent read gets         1 cleanouts and rollbacks - consistent read gets         1 immediate (CR) block cleanout applications         1 deferred (CURRENT) block cleanout applications         1 active txn count during cleanout         1 cleanout - number of ktugct calls         1 KTFB alloc req   1048576 KTFB alloc space (block)        42 KTFB alloc time (ms)         1 KTFB apply req         9 KTFB apply time (ms)         3 table scans (short tables)        21 table scan rows gotten        21 table scan disk non-IMC rows gotten         3 table scan blocks gotten      1194 table fetch by rowid         1 table fetch continued row         2 cluster key scans         2 cluster key scan block gets        17 rows fetched via callback        19 index fetch by key        11 index scans kdiixs1      1171 HSC Compressed Segment Block Changes      1172 HSC Heap Segment Block Changes         1 Heap Segment Array Updates         2 sql area evicted         3 CCursor + sql area evicted     10529 session cursor cache hits        26 session cursor cache count        11 cursor authentications      1763 buffer is pinned count       651 buffer is not pinned count         2 workarea executions - optimal         2 parse time cpu         1 parse time elapsed        50 parse count (total)        31 parse count (hard)     10559 execute count      6939 bytes sent via SQL*Net to client      7490 bytes received via SQL*Net from client        24 SQL*Net roundtrips to/from client        15 sorts (memory)         4 sorts (rows)       188 cell flash cache read hits113 rows selected.SQL> select * from v$session_event where sid = 1059;       SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS                    CON_ID---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- ------------------------- ----------      1059 Disk file operations I/O                          20              0           0            0          0               305  166678035    1740759767           8 User I/O                          33      1059 resmgr:cpu quantum                                28              0         136         4.86         43           1361254 1452455426    2396326234          10 Scheduler                         33      1059 SQL*Net message to client                         24              0           0            0          0                88 2067390145    2000153315           7 Network                           33      1059 SQL*Net message from client                       23              0       11436       497.21       4053         114357267 1421975091    2723168908           6 Idle                              33      1059 cell single block physical read                  188              0          10          .05          3            103309 2614864156    1740759767           8 User I/O                          335 rows selected.

Are you suggesting I should change the FK definitions to NOT do a 'on delete cascade'?   It looks like 'CASCADE' and 'SET NULL' would both search the other tables for related rows.

In this case I have already deleted any related rows based on the list of IDs (claims) that meet the criteria.

Is there a way to force the database to NOT read the related tables?

I'm going to review the values you commented on to see how they're relevant to add to my understanding.

Thanks very much for your help!!

-gary

Jonathan Lewis

It is worth noting that setting that parameter has had the expected effect. The number of "index fast full scans" has dropped by 3,510, even though the execution count has not changed; and the number of consistent gets has dropped from 56M to 40M - which gives us some idea of how big the three indexes were.

I will repeat

You need to enable sql_trace and run the delete, then apply tkprof to the resulting trace file, with the option "sort=exeqry"; this will bring the queries that do most consistent gets to the top of the output, and will identify which child tables are the ones to investigate.

I am NOT telling you to change the constraint definition, I'm telling you where I think the work is going, and while the constraint are defined with ON DELETE CASCADE we will be able to see the delete statement that Oracle has to run and we will see how expensive each one is. Alternatively we may see that none of the delete statements is at all expensive and that will tell us that we have to look elsewhere for the problem.

An alternative way of measuing - if you can't get at trace files but can get a dynamic performance views - is to query v$segment_statistics

SQL> desc v$segment_statistics

Name                                      Null?    Type

----------------------------------------- -------- ----------------------------

OWNER                                              VARCHAR2(128)

OBJECT_NAME                                        VARCHAR2(128)

SUBOBJECT_NAME                                     VARCHAR2(128)

TABLESPACE_NAME                                    VARCHAR2(30)

TS#                                                NUMBER

OBJ#                                               NUMBER

DATAOBJ#                                           NUMBER

OBJECT_TYPE                                        VARCHAR2(18)

STATISTIC_NAME                                     VARCHAR2(64)

STATISTIC#                                         NUMBER

VALUE                                              NUMBER

CON_ID                                             NUMBER

You're interested in the names of the parent table, the lob segment, the lob index, and all the foreign key indexes on the child tables, (and, I suppose, the child tables themselves).  The statistic_name you want to report  is: 'logical reads'.  Since it's a global view you'll have to:

query v$segment_statistics

run your delete

query v$segment_statistics

and then find the difference between the two sets of stats.

Regards

Jonathan Lewis

P.S.  You may have deleted all the related rows, but the optimizer doesn't know this and that's why it runs the delete statement. Although Oracle is NOT reporting tablescans I do wonder if some large fraction of the consistent gets is about tablescans, and that's why the extended trace is the ideal strategy. Another possibility is that some of the foreign key indexes have developed very long regions of empty blocks following your bulk delete tests and Oracle is having to walk through lots of empty index leaf blocks to find that there's no data. The reason why leaving Oracle to the default "on delete restrict" would make a difference is that Oracle would only try to lock the related index leaf blocks it wouldn't be trying to to optimise a delete statement - and that might make a difference to the work needed.

Jonathan Lewis

A possible solution to the tablescan puzzle has occurred to me, Oracle may be running the delete child statements as index skip scans (or even index full scans) on a very bad choice of index.  It makes me wonder what your "optimizer_index_%' parameters look like - have they be set to values that hide the actual cost of indexed accesses. (e.g. optimizer_index_cost_adjust = 1, optimizer_index_caching = 100).

Another option (and simpler than the v$segment_statistics one) if you can't get at trace files is to run the delete and then query v$sql:

select sql_id, child_number, executions, buffer_gets, rows_processed, sql_text

from v$sql

where sql_text like ' delete%'  -- note the leading space

order by last_active_time

/

What you're looking for is the recursive deletes on the child tables where the number of buffer_gets is very large (or very large per execution). The rows_processed should be zero, of course, if you've deleted all the related rows from the child table before deleting from the CLOB table.

The full text should look like the following (and the leading space is supposed to be there):

' delete from "TEST_USER"."T2" where "ID_PAR" = :1'

If you spot any suspect statements with very large values of buffer_gets then you can do:

select * from table(dbms_xplan.display_cursor({sql_id},{child_number},'outline'));

to get the execution plan and optimizer environment details.

Regards

Jonathan Lewis

4101461

Jonathan

Since I am explicitly deleting the related rows from the child tables before I try to delete the rows from the parent table, what are the potential problems, if any,  with temporarily disabling the FKs, doing the delete and re-enabling the FKs immediately afterwards?

This purge operation is run at night when there are no users in the application.

I just did a test using the same 1170 rows and the delete was pretty much instantaneous.

It obviously takes some time to re-enable the constraints but the time for that operation is only minutes in my 1170 row example.

Thoughts?

Thanks again for all your help!!!!

-gary

Jonathan Lewis

Gary,

You've already covered the two critical issues -

a) what if someone inserts some bad data between your drop and create of the foreign key constraint

b) how long does it take to re-enable the constraint.

There's also the detail of how long it will take to do the large scale deletes and whether that will leave you more vulnerable to an unexpected end user having a chance to create bad data. In principle, though, if you are aware of the risks then dropping and recreating the constraints is an option you could take.

I'd raise the question of why the constraint is "on delete cascade" though - is this a necessity or could the application be easily modified to delete child rows before deleting a parent - leaving the constraint to Oracle's default "on delete restrict".  If that's a viable option then a test of whether you would still see a massive logical I/O overhead would still be relevant.

I'd like to point out two things, though.

People help each other on this forum because sometimes they learn from helping. I'm helping you because I want to know where those 40M logical I/Os are coming from because they shouldn't (in principle) be happening. Oracle has a low-cost foreign key check for "on delete restrict" that it can use to check "on delete cascade" and bypass the delete statement (as you surmised) - so I want to be sure that the extra logical I/O is coming from redundant deletes (I'd also like to know why it's possible for that to happen) so I've made a suggestion to help you but it's a suggestion that I actually want to see the results from - that's my payback for helping.

The second point is that you ought to want to confirm the same thing - because if it's not the foreign key DELETE statement then whatever it is might happen effectively randomly some time you're trying to do a 98,000 row delete, leaving you in a position where you have to interrupt a very long running process to roll it back and recreate the foreign key constraints in a rush because you've run out of time.

Regards

Jonathan Lewis

4101461

Jonathan

I hear you and will give you (and me) as much feedback as I can.  I truly appreciate your help.

My first issue is that I'm running on Oracle 12.1.0.2 and it doesn't appear that 'ON DELETE RESTRICT' is a valid option.  My docs say 'CASCADE' and 'SET NULL' are the only two I have available.  I have recreated the FKs but did not include the 'ON DELETE' clause and it looks like the DELETE_RULE for the constraints is now 'NO ACTION'.  I hope that's what turns off the child table searching.

I will re-create the 1170 row delete and post the findings ...

==================

OK, the deletion of the 1170 rows still took about 20 minutes.  Apparently removing the ON DELETE clause of the FKs didn't make a difference even though the DELETE_RULE now says 'NO ACTION'.

Here are the results of the SQL statements.  It seems to show the database still searching the child tables for potential parent values.

I only got a few lines from V$SQL:

SQL> select sql_id, child_number, executions, buffer_gets, rows_processed, sql_text from v$sql where sql_text like ' delete%'  order by last_active_time;SQL_ID        CHILD_NUMBER EXECUTIONS BUFFER_GETS ROWS_PROCESSED SQL_TEXT------------- ------------ ---------- ----------- -------------- ----------------------------------------------------------------------1z5usw7f6h0hs            0       1170      107691              0  delete from "EDI_MSTR"."VALUECODES" where "CLAIMID" = :12q37gp1d7b85x            0       1170     1474232              0  delete from "EDI_MSTR"."EXTERNALCAUSEOFINJURIES" where "CLAIMID" = :12q37gp1d7b85x            1       1170      453149              0  delete from "EDI_MSTR"."EXTERNALCAUSEOFINJURIES" where "CLAIMID" = :11z5usw7f6h0hs            1       1170      107643              0  delete from "EDI_MSTR"."VALUECODES" where "CLAIMID" = :1

I wasn't able to get an explain plan.

SQL>  select * from v$session_event where sid = 5018;       SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS                    CON_ID---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- ------------------------- ----------      5018 Disk file operations I/O                          25              0           0            0          0               343  166678035    1740759767           8 User I/O                          33      5018 log file sync                                      1              0           0          .16          0              1592 1328744198    3386400367           5 Commit                            33      5018 resmgr:cpu quantum                                10              0         131         13.1         45           1309712 1452455426    2396326234          10 Scheduler                         33      5018 SQL*Net message to client                         20              0           0            0          0                49 2067390145    2000153315           7 Network                           33      5018 SQL*Net message from client                       19              0      123743      6512.81     122432        1237433474 1421975091    2723168908           6 Idle                              33      5018 cell single block physical read                18601              0         551          .03          2           5514812 2614864156    1740759767           8 User I/O                          33      5018 cell multiblock physical read                   1599              0          65          .04          0            647471  443865681    1740759767           8 User I/O                          33      5018 cell list of blocks physical read                  1              0           0          .03          0               293 3975960017    1740759767           8 User I/O                          33

SQL> select ss.value, sn.name from v$sesstat ss, v$statname sn where ss.statistic# = sn.statistic# and sid = 5018 and value != 0;     VALUE NAME     VALUE NAME---------- ----------------------------------------------------------------        19 Requests to/from client         1 logons cumulative         1 logons current      9390 opened cursors cumulative         4 opened cursors current        28 user calls     28273 recursive calls    115398 recursive cpu usage         1 pinned cursors current         1 user logons cumulative  56167876 session logical reads    115528 CPU used when call started    115528 CPU used by this session    116403 DB time       616 user I/O wait time       130 scheduler wait time       747 non-idle wait time     40469 non-idle wait count1597167075 session connect time1597167075 process last non-idle time    544696 session uga memory    544696 session uga memory max         5 messages sent   2313864 session pga memory   2772616 session pga memory max     12940 enqueue requests      1170 enqueue conversions     12934 enqueue releases     20204 physical read total IO requests       150 physical read total multi block requests     20204 physical read requests optimized 248225792 physical read total bytes optimized 248225792 physical read total bytes 248225792 cell physical IO interconnect bytes     31195 db block gets     31195 db block gets from cache     16410 db block gets from cache (fastpath)  56136681 consistent gets  56136681 consistent gets from cache  56136644 consistent gets pin  56117137 consistent gets pin (fastpath)        37 consistent gets examination        31 consistent gets examination (fastpath)4.6013E+11 logical read bytes from cache     30301 physical reads     30301 physical reads cache     20204 physical read IO requests 248225792 physical read bytes      6552 db block changes         1 consistent changes         3 change write time     30880 free buffer requested       307 dirty buffers inspected         7 pinned buffers inspected      7638 hot buffers moved to head of LRU     29774 free buffer inspected         1 commit cleanouts         1 commit cleanouts successfully completed         1 CR blocks created       578 switch current to new buffer     10100 physical reads cache prefetch      4193 shared hash latch upgrades - no wait       576 physical reads for flashback new     58560 calls to kcmgcs         2 calls to kcmgas     12923 calls to get snapshot scn: kcmgss      3551 redo entries   4373080 redo size        17 redo subscn max counts      1601 redo synch time (usec)        26 redo synch time overhead (usec)         1 redo synch time overhead count (  2ms)         1 redo synch writes         1 redo write info find   6162587 file io wait time   3853712 undo change vector size         1 data blocks consistent reads - undo records applied  56078134 no work - consistent read gets         1 cleanouts and rollbacks - consistent read gets         1 immediate (CR) block cleanout applications         1 deferred (CURRENT) block cleanout applications         1 active txn count during cleanout         1 cleanout - number of ktugct calls         5 KTFB alloc req   5242880 KTFB alloc space (block)       281 KTFB alloc time (ms)         5 KTFB apply req        78 KTFB apply time (ms)         3 table scans (short tables)        21 table scan rows gotten        21 table scan disk non-IMC rows gotten         3 table scan blocks gotten      1188 table fetch by rowid         1 table fetch continued row         4 cluster key scans         4 cluster key scan block gets         7 rows fetched via callback      3510 index fast full scans (full)        11 index fetch by key        14 index scans kdiixs1      1171 HSC Compressed Segment Block Changes      1172 HSC Heap Segment Block Changes         1 Heap Segment Array Updates         1 CCursor + sql area evicted      9359 session cursor cache hits         8 session cursor cache count         8 cursor authentications      1767 buffer is pinned count       642 buffer is not pinned count         9 workarea executions - optimal         1 parse time cpu         2 parse time elapsed        45 parse count (total)        26 parse count (hard)      9388 execute count      6186 bytes sent via SQL*Net to client      6199 bytes received via SQL*Net from client        20 SQL*Net roundtrips to/from client        19 sorts (memory)      3516 sorts (rows)     20204 cell flash cache read hits----------------------------------------------

I'm not sure how to prevent the database from doing the child table searches.  Advice needed please.

I was going to try and disable the FKs before the DELETE and re-enable them afterwards.  That seemed to work in my smaller DEV environment.  Thoughts?

I understand the risks of modifying the FKs in a 'live' application but if the usage is controlled with no users at night it might be the best solution.

Thanks very much for your help.

-gary

4101461

I have taken the route of disabling the FKs before I delete the rows from the parent table and re-enabling them afterwards.

Since I have explicitly deleted all the child rows as the first step in the process I'm quite certain I won't be creating any orphan child rows.

I am going to schedule the purge job during a low activity time when there is no data loading.

I want to thank everyone who commented on this topic, especially Jonathan, and I hope I have provided enough feedback to make his efforts worthwhile.  If not, please let me know what additional information you'd like to see.

-gary

Jonathan Lewis

My first issue is that I'm running on Oracle 12.1.0.2 and it doesn't appear that 'ON DELETE RESTRICT' is a valid option.  My docs say 'CASCADE' and 'SET NULL' are the only two I have available.  I have recreated the FKs but did not include the 'ON DELETE' clause and it looks like the DELETE_RULE for the constraints is now 'NO ACTION'.  I hope that's what turns off the child table searching.

My error - "on delete restrict" may be the formal ANSI declaration, or maybe it's an informal description that appeared in the Oracle manuals, but it's the default option that you get if you don't specify "on delete" at all - and it means you can't delete the parent if there are current child rows.

SQL_ID        CHILD_NUMBER EXECUTIONS BUFFER_GETS ROWS_PROCESSED SQL_TEXT  ------------- ------------ ---------- ----------- -------------- ----------------------------------------------------------------------  1z5usw7f6h0hs            0       1170      107691              0  delete from "EDI_MSTR"."VALUECODES" where "CLAIMID" = :1  2q37gp1d7b85x            0       1170     1474232              0  delete from "EDI_MSTR"."EXTERNALCAUSEOFINJURIES" where "CLAIMID" = :1  2q37gp1d7b85x            1       1170      453149              0  delete from "EDI_MSTR"."EXTERNALCAUSEOFINJURIES" where "CLAIMID" = :1  1z5usw7f6h0hs            1       1170      107643              0  delete from "EDI_MSTR"."VALUECODES" where "CLAIMID" = :1  

If those delete statements appeared in the current test, and weren't left over from a previous test then you still have some foreign key constraints defined with ON DELETE CASCADE.

      9388 execute count  

And the execute count suggests fairly strongly you have 8 foreign key constraints with ON DELETE CASCADE.

Regards

Jonathan Lewis

Jonathan Lewis

I am going to schedule the purge job during a low activity time when there is no data loading.

Have you had a chance to run the purge yet ?

How did it go?

Did any other bottlenexk show up once you'd got past the foreign key problem?

Regards

Jonathan Lewis

4101461

Hi Jonathan

I did create the script to disable the FKs on the CLAIMS table I'm trying to delete from and re-enable them afterwards.

I was able to delete several hundred thousand rows in just a few minutes as opposed to 20 minutes for 1170 rows with the FKs enabled.

I have not checked the run statistics from the above views as before with the modified script but will try to do it tomorrow morning.

I have made each run independent of each other to make the statistics reflect only the single run.

I'll report the new data as soon as I capture it.

Thanks again for all your help.  Please let me know what other feedback you'd like to see from this exercise.

-gary

Jonathan Lewis

gary,

You've got something you're happy with, so all's fine.

I am still curious about the test where you changed the foreign key constraints so that they were (in Oracle-speak) "on delete no action", because the supporting detail you supplied to that test suggested Oracle was still doing "on delete cascade" and that doesn't happen when I run up a copy of 12.1.0.2.

However you'd have to run through the entire test recording every detail and reporting the foreign key constraints en route and capture the trace files to prove the point (and I'm not going to ask you to do that just to satisfy my curiousity.)

Regards

JOnathan Lewis

Jonathan Lewis

Gary,

I can't manage to leave this one alone. Your system seems to be doing something that shouldn't happen.

The only way I can emulate your results is to get rid of (EDIT: or define as bitmaps) the indexes that protect the foreign keys - specifically that's getting the "execute count" that you were seeing. I know that in an earlier post you said you had indexes on the foreign keys - are you absolutely sure that this is correct, and if so are they B-tree indexes (bitmap indexes don't count) that start with the foreign key column?

Otherwise is there anything (apart from the CLOB column in the parent) about any of the tables involved that makes them anything more subtle than basic heap tables with b-tree indexes ?

Regards

Jonathan Lewis

4101461

Jonathan

I just entered a huge reply with lots of stats and the web site won't take it.

I'll try attaching the data as a file.

Sorry for the delay!

-gary

4101461

Jonathan

Let's try by adding all the stats as a file.

-gary