excessive db block gets and cpu usage

From: krishna sarabu <ksarabu_at_yahoo.com>
Date: Tue, 28 Jul 2009 06:20:32 -0700 (PDT)
Message-ID: <212670.34122.qm_at_web56205.mail.re3.yahoo.com>



 

Hi,
 

The database version is 10.2.0.3.
 

I have started noticing excessive db block gets for frequent ddls and/or txn commits and that was causing CPU spike.
 

A simple test case, to truncate empty table in 100 iterations caused 2 million db block gets and the 10046 trace trace revealed nothing. It's just burning CPU, and no waits. I've turned-off "_dml_monitoring_enabled"=false and that did not help. fyi, attaching below the 10046 trace (taken when "_dml_monitoring_enabled" was set to default "true").
 

Not sure if we have any internal event to help tracing current reads. Can anyone please help me to identify the root cause?
 

Thanks in advance.

truncate table testme

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse      100      0.04       0.06          0          0          0           0
Execute    100     43.16      43.56         31       6436    2177931           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      200     43.20      43.63         31       6436    2177931           0


Misses in library cache during parse: 100 Optimizer mode: ALL_ROWS
Parsing user id: 160 (recursive depth: 1)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         6        0.00          0.01
  reliable message                                1        0.00          0.00
  enq: RO - fast object reuse                     1        0.00          0.00
  local write wait                                3        0.00          0.00
  log file sync                                  13        0.04          0.11
  rdbms ipc reply                               112        0.07          0.21
********************************************************************************


update sys.mon_mods$ set inserts = inserts + :ins, updates = updates + :upd,   deletes = deletes + :del, flags = (decode(bitand(flags, :flag), :flag,   flags, flags + :flag)), drop_segments = drop_segments + :dropseg, timestamp

  • :time where obj# = :objn

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse      100      0.01       0.00          0          0          0           0
Execute    100     35.90      35.25          0        607    1979473         100
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      200     35.91      35.26          0        607    1979473         100


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

Rows Row Source Operation

-------  ---------------------------------------------------
      1  UPDATE  MON_MODS$ (cr=1 pr=0 pw=0 time=417 us)
      1   INDEX UNIQUE SCAN I_MON_MODS$_OBJ (cr=1 pr=0 pw=0 time=13 us)(object id 483)




Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  rdbms ipc reply                               110        0.01          0.13
********************************************************************************


begin
for i in 1..100 loop
  execute immediate 'truncate table testme'; end loop;
end;

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.04       0.02          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.04       0.03          0          0          0           1


Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 160

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
*****************************************************************************

 

Rgds,
Krishna       
--
http://www.freelists.org/webpage/oracle-l
Received on Tue Jul 28 2009 - 08:20:32 CDT

Original text of this message