This discussion is archived
1 2 Previous Next 25 Replies Latest reply: May 27, 2013 3:34 PM by Jonathan Lewis RSS

db block gets while delete

kamilp Newbie
Currently Being Moderated
Hi,

below is the query and its execution plan. From plan I would expect the delete command to be processed very quickly, however it does huge amounts of db block gets. I assume this is because of deleting the row from other structures (indexes, foreign keys in tables etc.)
How can I find out which object scan caused the db block gets ?


SQL> delete from messages2 where id = 11004240718;

1 row deleted.

Elapsed: 00:00:03.79

Execution Plan
----------------------------------------------------------
Plan hash value: 140582024

-----------------------------------------------------------------------------------
| Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | DELETE STATEMENT   |              |     1 |    17 |     2   (0)| 00:00:01 |
|   1 |  DELETE            | MESSAGES2    |       |       |            |          |
|*  2 |   INDEX UNIQUE SCAN| SYS_C0016189 |     1 |    17 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ID"=11004240718)


Statistics
----------------------------------------------------------
         61  recursive calls
       7381  db block gets
         92  consistent gets
       5802  physical reads
     303368  redo size
        839  bytes sent via SQL*Net to client
        801  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
          1  rows processed
Edited by: kamilp on May 21, 2013 10:02 PM
  • 1. Re: db block gets while delete
    davidp 2 Pro
    Currently Being Moderated
    61 recursive calls
    That is 61 other queries triggered while processing your query. Had you just restarted the DB or flushed the shared pool ? It could have been SQL used to get statistics when parsing the delete statement.
    Are there triggers on the table doing other work ?
    Are there cascaded constraints ?
    If you turn SQL_TRACE on (alter session set sql_trace=true), get the trace file and run tkprof on it, you will see what the session did, including the recursive SQL.
    The other possibility for lots of I/O for a simple delete is lots of current block reconstruction because of uncommitted transactions on the table (especially uncommitted inserts in this case).
  • 2. Re: db block gets while delete
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    Updates to Table and Index blocks are executed by retrieving those blocks as "db block get"s -- is Current Gets.

    However, the numbers seem very high. What is the structure of the table ? How many indexes doe it have (every index needs to be updated for the DELETE) ? Are there FK constraints defined with "ON DELETE CASCADE" (which would cascade to a child tables and it's indexes) ?


    Hemant K Chitale
  • 3. Re: db block gets while delete
    kamilp Newbie
    Currently Being Moderated
    Are there triggers on the table doing other work ?
    no triggers on the table
    Are there cascaded constraints ?
    i need to check database for cascaded constraints, but as far as I know there are none on the table.


    here is the table structure
    SQL> desc messages2
     Name                                                  Null?    Type
     ----------------------------------------------------- -------- ------------------------------------
     ID                                                    NOT NULL NUMBER(38)
     PHEADER                                                        VARCHAR2(64)
     MSG                                                            LONG RAW
     TIME                                                           NUMBER(38)
     ENCODING                                                       VARCHAR2(32)
     METADATA_ID                                                    NUMBER(38)
    there are 2 indexes on the table
    Schema.Index     Indexed Columns     Column Position
    IMS.MESSAGES2_IDX_T     TIME     1
    IMS.SYS_C0016189     ID     1
    there are several other tables with foreign key constraint on the messages2.id column, i checked the indexes on those columns and all are indexed.



    below is the tkprof output
    ********************************************************************************
    
    SQL ID: 84pwtaks8qnqf Plan Hash: 140582024
    
    delete from messages2 
    where
     id = 13032713632
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.01       0.01          0          3       7269           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.01       0.01          0          3       7269           1
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 70  
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             0          0          0  DELETE  MESSAGES2 (cr=3 pr=0 pw=0 time=13210 us)
             1          1          1   INDEX UNIQUE SCAN SYS_C0016189 (cr=3 pr=0 pw=0 time=28 us cost=2 size=17 card=1)(object id 81644)
    
    ********************************************************************************
     
    Edited by: kamilp on May 21, 2013 11:20 PM

    I have added also actual output from the production system
    TKPROF: Release 11.2.0.3.0 - Development on Wed May 22 06:46:08 2013
    
    Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.
    
    Trace file: orcl2_ora_21531.trc
    Sort options: default
    
    ********************************************************************************
    count    = number of times OCI procedure was executed
    cpu      = cpu time in seconds executing 
    elapsed  = elapsed time in seconds executing
    disk     = number of physical reads of buffers from disk
    query    = number of buffers gotten for consistent read
    current  = number of buffers gotten in current mode (usually for update)
    rows     = number of rows processed by the fetch or execute call
    ********************************************************************************
    
    SQL ID: 7sukcncaxjnxy Plan Hash: 140582024
    
    delete from messages2 
    where
     id = :1 
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse      396      0.00       0.00          0          0          0           0
    Execute    397     46.89      47.25          6       1191   60899400         397
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      793     46.90      47.26          6       1191   60899400         397
    
    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 70  
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             0          0          0  DELETE  MESSAGES2 (cr=3 pr=0 pw=0 time=119646 us)
             1          1          1   INDEX UNIQUE SCAN SYS_C0016189 (cr=3 pr=0 pw=0 time=26 us cost=2 size=17 card=1)(object id 81644)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                     396        0.00          0.00
      SQL*Net message from client                   396        0.09          0.37
      gc current grant 2-way                         33        0.00          0.01
      gc current grant congested                      2        0.00          0.00
      gc current block 2-way                          2        0.00          0.00
      gc current grant busy                           3        0.00          0.00
      gc current multi block request                  1        0.00          0.00
      db file scattered read                          1        0.00          0.00
    
    
    
    ********************************************************************************
    
    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse      396      0.00       0.00          0          0          0           0
    Execute    397     46.89      47.25          6       1191   60899400         397
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      793     46.90      47.26          6       1191   60899400         397
    
    Misses in library cache during parse: 0
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                     396        0.00          0.00
      SQL*Net message from client                   396        0.09          0.37
      gc current grant 2-way                         33        0.00          0.01
      gc current grant congested                      2        0.00          0.00
      gc current block 2-way                          2        0.00          0.00
      gc current grant busy                           3        0.00          0.00
      gc current multi block request                  1        0.00          0.00
      db file scattered read                          1        0.00          0.00
    
    
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      0      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        0      0.00       0.00          0          0          0           0
    
    Misses in library cache during parse: 0
    
        1  user  SQL statements in session.
        0  internal SQL statements in session.
        1  SQL statements in session.
    ********************************************************************************
    Trace file: orcl2_ora_21531.trc
    Trace file compatibility: 11.1.0.7
    Sort options: default
    
           1  session in tracefile.
           1  user  SQL statements in trace file.
           0  internal SQL statements in trace file.
           1  SQL statements in trace file.
           1  unique SQL statements in trace file.
        4534  lines in trace file.
          47  elapsed seconds in trace file.
  • 4. Re: db block gets while delete
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    You should go through the raw trace file to identify the "child" tables where rows have been deleted from -- the deletes in these tables would have been executed as recursive SQLs. The child tables and their delete SQL statements would not appear in the tkprof.


    Hemant K Chitale
  • 5. Re: db block gets while delete
    kamilp Newbie
    Currently Being Moderated
    after enabling/disabling constraints I have found exactly 1 constraint that causes high db block gets while my delete
    SQL> delete from messages2 where id = 13032713632;
    
    1 row deleted.
    
    Elapsed: 00:00:00.01
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 140582024
    
    -----------------------------------------------------------------------------------
    | Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    -----------------------------------------------------------------------------------
    |   0 | DELETE STATEMENT   |              |     1 |    17 |     2   (0)| 00:00:01 |
    |   1 |  DELETE            | MESSAGES2    |       |       |            |          |
    |*  2 |   INDEX UNIQUE SCAN| SYS_C0016189 |     1 |    17 |     2   (0)| 00:00:01 |
    -----------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("ID"=13032713632)
    
    
    Statistics
    ----------------------------------------------------------
             55  recursive calls
             15  db block gets
             90  consistent gets
              0  physical reads
           1028  redo size
            849  bytes sent via SQL*Net to client
            801  bytes received via SQL*Net from client
              3  SQL*Net roundtrips to/from client
              5  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    SQL> rollback;
    and now with enabled constraint:
    SQL> alter table folders2 enable constraint SYS_C0016199;
    
    Table altered.
    
    Elapsed: 00:01:20.68
    SQL> delete from messages2 where id = 13032713632;
    
    1 row deleted.
    
    Elapsed: 00:00:00.01
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 140582024
    
    -----------------------------------------------------------------------------------
    | Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    -----------------------------------------------------------------------------------
    |   0 | DELETE STATEMENT   |              |     1 |    17 |     2   (0)| 00:00:01 |
    |   1 |  DELETE            | MESSAGES2    |       |       |            |          |
    |*  2 |   INDEX UNIQUE SCAN| SYS_C0016189 |     1 |    17 |     2   (0)| 00:00:01 |
    -----------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("ID"=13032713632)
    
    
    Statistics
    ----------------------------------------------------------
             37  recursive calls
           7209  db block gets
             61  consistent gets
              0  physical reads
           1028  redo size
            850  bytes sent via SQL*Net to client
            801  bytes received via SQL*Net from client
              3  SQL*Net roundtrips to/from client
              5  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    SQL> rollback;
    There is index on the table folders2 column message_id
    CREATE TABLE "MSS"."FOLDERS2" ( "ID" NUMBER, "PHEADER" VARCHAR2(64), "CFNUMBER" NUMBER, "TIME" NUMBER, "MESSAGE_ID" NUMBER, "METADATA_ID" NUMBER, PRIMARY KEY ("ID") VALIDATE , FOREIGN KEY ("MESSAGE_ID") REFERENCES "MSS"."MESSAGES2" ("ID") DISABLE NOVALIDATE , FOREIGN KEY ("METADATA_ID") REFERENCES "MSS"."METADATA2" ("ID") VALIDATE ) TABLESPACE "USERS" PCTFREE 10 INITRANS 1 MAXTRANS 255 STORAGE ( INITIAL 64K BUFFER_POOL DEFAULT) LOGGING NOCOMPRES
    CREATE INDEX "MSS"."FOLDERS2_IDX_MI" ON "MSS"."FOLDERS2" ("MESSAGE_ID") TABLESPACE "USERS" PCTFREE 10 INITRANS 2 MAXTRANS 255 STORAGE ( INITIAL 64K BUFFER_POOL DEFAULT) LOGGING LOCAL
    Edited by: kamilp on May 22, 2013 5:51 AM
  • 6. Re: db block gets while delete
    davidp 2 Pro
    Currently Being Moderated
    It looks to me like you have lots of activity on the table, including some long uncommitted transactions, and a lot of work is being done reconstructing a consistent view of the committed contents of the database block for the index or table block.
    What statistics do you get on a single user test database with the same data ? I expect you will find far far less I/O. If so, investigate whether the long uncommitted transactions can be made to commit at suitable points (still atomic transactions) that are more frequent.
  • 7. Re: db block gets while delete
    davidp 2 Pro
    Currently Being Moderated
    It sounds like this relates to your earlier messaging query {message:id=10594831}
    Have you looked at using Advanced Queueing http://docs.oracle.com/cd/E11882_01/server.112/e11013/toc.htm possibly using buffered messaging ? In implementing Advanced Queueing, Oracle have addressed the performance issues you are encountering. I have used it successfully with 100's of messages a second with persistent messaging.
    Note: I think buffered messaging has difficulties on a RAC cluster - because of needing to internally connect to the node that is hosting the queue, I think you need to have connected with an explicit password, not via O/S authentication.
  • 8. Re: db block gets while delete
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    alter table folders2 enable constraint SYS_C0016199;
    I guess that this is a Foreign Key constraint defined with ON DELETE CASCADE. And there are mutliple records in the folders2 table for the same id from the messages2 table. The db block gets would be for the folders2 records and index entries.


    Hemant K Chitale
  • 9. Re: db block gets while delete
    kamilp Newbie
    Currently Being Moderated
    Hi,

    regarding my previous thread - this is related problem to same table structure and application. Using "Advanced Queueing" is not applicable at the moment, altought I understand it would be of great benefit. We can not afford changing application logic and importantly - the table design and bussines logic is required by customers.
    - tuning off any other activity except the above mentioned delete on table does not help
    - the hardware is oracle database applicance (2 node rac)
    - no on delete cascade (application maintains the foreign key tables, indeed we could turn off foreign keys because of application design, but I want them keep turned on)

    The problem could be caused by stale indexes. The amount of inserts/deletes on the table is large and exceeds much over 10 percent per day. In other similar systems we maintan the amount of insert/delete is much less than 10 percent per day.

    Edited by: kamilp on May 22, 2013 11:04 PM
  • 10. Re: db block gets while delete
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    no on delete cascade
    If so, then enabling that one identified constraint would not cause so may db block gets.

    Go through the raw trace file to identify which object those 7209 blocks are read from -- hopefully, Oracle did physical reads from disk and you would find the object and block information against 'db file sequential read' (or even 'db file scattered read')


    Hemant K Chitale
  • 11. Re: db block gets while delete
    davidp 2 Pro
    Currently Being Moderated
    It sounds like you have an extremely busy single index block - lots of threads writing and deleting messages in ascending message ID's, with the deleted and inserts all happening in the top block of the index. If you only ever access the table with equality queries on the message_no, you could distribute the messages across more blocks by using a variety of keys or reverse indexing. If you need to have ascending message_no and searches in order, you can reduce the load on the index by:
    1. Messages are written as now.
    2. Consumers update the message with a status saying the message has been processed, so no other consumer uses it, but leave the row in the index. Do not index that status flag.
    3. every 5 minutes a batch process cleans up processed messages.
    This means writers are filling an index block and moving on to the next without the block being continually updated by consumers.
    Every 5 minutes the clean up process removes messages that are mostly in inactive blocks, and only one delete transaction affects a block at a time.
  • 12. Re: db block gets while delete
    kamilp Newbie
    Currently Being Moderated
    I have rewriten the deleter process from java&jdbc to pl/sql procedure and speed of deleting data increased rapidly. I am not sure what was the problem with java & jdbc code. Could be that in pl/sql I used bulk operations, while jdbc was using one call per one row.
    Anyway, I would be interrested how to find the disk operations from trc file. I have investigated it and I have not found from which files or objects it reads data. here is my trace file
    Trace file /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_ora_30220.trc
    Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
    With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
    Data Mining and Real Application Testing options
    ORACLE_HOME = /u01/app/oracle/product/11.2.0.3/dbhome_1
    System name:    Linux
    Node name:      orcl1
    Release:        2.6.32-300.32.4.el5uek
    Version:        #1 SMP Mon Oct 8 20:32:47 PDT 2012
    Machine:        x86_64
    Instance name: orcl1
    Redo thread mounted by this instance: 1
    Oracle process number: 36
    Unix process pid: 30220, image: oracle@orcl1 (TNS V1-V3)
    
    
    *** 2013-05-22 06:15:11.401
    *** SESSION ID:(1826.29591) 2013-05-22 06:15:11.401
    *** CLIENT ID:() 2013-05-22 06:15:11.401
    *** SERVICE NAME:(SYS$USERS) 2013-05-22 06:15:11.401
    *** MODULE NAME:(SQL*Plus) 2013-05-22 06:15:11.401
    *** ACTION NAME:() 2013-05-22 06:15:11.401
    
    =====================
    PARSING IN CURSOR #140557115442928 len=32 dep=0 uid=70 oct=42 lid=70 tim=1369203311400843 hv=1569151342 ad='7fd600ebfe10' sqlid='4tk6t8tfsfqbf'
    alter session set sql_trace=true
    END OF STMT
    EXEC #140557115442928:c=0,e=42,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1369203311400838
    
    *** 2013-05-22 06:15:16.385
    CLOSE #140557115442928:c=0,e=5,dep=0,type=0,tim=1369203316385024
    =====================
    PARSING IN CURSOR #140557115442928 len=44 dep=0 uid=70 oct=7 lid=70 tim=1369203316386617 hv=1195005464 ad='c2f5400c0' sqlid='50bs1f13mnphs'
    delete from messages2 where id = 13032713628
    END OF STMT
    PARSE #140557115442928:c=0,e=1528,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=140582024,tim=1369203316386615
    EXEC #140557115442928:c=13998,e=31083,p=4,cr=3,cu=7271,mis=0,r=1,dep=0,og=1,plh=140582024,tim=1369203316417749
    STAT #140557115442928 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE  MESSAGES2 (cr=3 pr=4 pw=0 time=30986 us)'
    STAT #140557115442928 id=2 cnt=1 pid=1 pos=1 obj=81644 op='INDEX UNIQUE SCAN SYS_C0016189 (cr=3 pr=1 pw=0 time=3757 us cost=2 size=17 card=1)'
    
    *** 2013-05-22 06:15:26.851
    CLOSE #140557115442928:c=0,e=6,dep=0,type=0,tim=1369203326851020
    =====================
    PARSING IN CURSOR #140557115442928 len=33 dep=0 uid=70 oct=42 lid=70 tim=1369203326851554 hv=525901419 ad='7fd600ebfe10' sqlid='aam2chsgpj7mb'
    alter session set sql_trace=false
    END OF STMT
    PARSE #140557115442928:c=0,e=450,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1369203326851553
    EXEC #140557115442928:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1369203326851634
  • 13. Re: db block gets while delete
    kamilp Newbie
    Currently Being Moderated
    Hi people,

    I come to same situation with pl/sql procedure - the delete operation is slow having a lots of bufer gets for every operation. Here is info from testing database execution statistics
    SQL> select to_char(min(id)) from messages2;
    
    TO_CHAR(MIN(ID))
    ----------------------------------------
    138065761031
    
    Elapsed: 00:00:00.17
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 1212472277
    
    -------------------------------------------------------------------------------------------
    | Id  | Operation                  | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT           |              |     1 |     8 |     4   (0)| 00:00:01 |
    |   1 |  SORT AGGREGATE            |              |     1 |     8 |            |          |
    |   2 |   INDEX FULL SCAN (MIN/MAX)| SYS_C0014687 |     1 |     8 |     4   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------------
    
    
    Statistics
    ----------------------------------------------------------
              1  recursive calls
              0  db block gets
           2096  consistent gets
             19  physical reads
            952  redo size
            544  bytes sent via SQL*Net to client
            524  bytes received via SQL*Net from client
              2  SQL*Net roundtrips to/from client
              0  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    SQL> delete from messages2 where id = 138065761031;
    
    1 row deleted.
    
    Elapsed: 00:00:09.14
    
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 1420548849
    
    -----------------------------------------------------------------------------------
    | Id  | Operation          | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
    -----------------------------------------------------------------------------------
    |   0 | DELETE STATEMENT   |              |     1 |    17 |     3   (0)| 00:00:01 |
    |   1 |  DELETE            | MESSAGES2    |       |       |            |          |
    |*  2 |   INDEX UNIQUE SCAN| SYS_C0014687 |     1 |    17 |     3   (0)| 00:00:01 |
    -----------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("ID"=138065761031)
    
    
    Statistics
    ----------------------------------------------------------
              1  recursive calls
         186719  db block gets
              4  consistent gets
           2094  physical reads
            936  redo size
            847  bytes sent via SQL*Net to client
            802  bytes received via SQL*Net from client
              3  SQL*Net roundtrips to/from client
              1  sorts (memory)
              0  sorts (disk)
              1  rows processed
    Unfortunatelly, the execution plan does not help me

    My question is - is there any tool to find out more details about the query execution ? I would like to know what objects is database scanning causing db block gets both in select and delete.

    Thanks
  • 14. Re: db block gets while delete
    rp0428 Guru
    Currently Being Moderated
    >
    SYS_C0014687
    >
    Where did that index come from? That's not the same one as before.
1 2 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points