Re[4]: what exactly 'tim' means in a 10046 TRACE file ?

From: Edgar Chupit <chupit_at_tsi.lv>
Date: Wed, 31 Mar 2004 19:34:53 +0300
Message-ID: <11223147765.20040331193453@tsi.lv>

Hello Anjo,

AK> 24381, 00000, "error(s) in array DML"
AK> // *Cause:  One or more rows failed in the DML.
AK> // *Action: Refer to the error stack in the error handle.

AK> that  will  consume  the  CPU. In fact your error is not really an

AK> error but an indication that the application need to check a AK> couple of rows of the array that failed.

It's exactly whats happening, but isn't error handling (such as checking that index block already filled with data, saving error information, something else?) consumes some amount of response time?

I've created test using Tom Kytes runstats_pkg and it shows that processing of duplicate rows consumes "some" amount of resources.

I have verified Niall hypothesis, but have found out that ERROR's tim value is value returned by v$timer (Note:43735.1): Time is measured since the beginning of the epoch, which is operating system specific, and wraps around to 0 again whenever the value overflows four bytes (roughly 497 days).

At least on Linux this seams to be true and to convert from gettimeofday to value that is returned from v$timer you simply need to strip highest bit something like tv_sec&~0x80000000 and this gives the same value as in tim line of trace file for ERROR line.

Here is my little test, could somebody confirm that by "fixing" application so it wouldn't insert "duplicate" rows we could perform better than now?

• test -- create table test1 ( id integer, value number )
  /
  

insert into test1
select rownum, rownum*rownum
from all_objects
where rownum < 1000
/

create unique index test1_pk on test1(id)
/

begin

    otis.runstats_pkg.rs_start;     

    declare

      type row_type is table of test1%rowtype;
      rw row_type;
    begin
       select id, value bulk collect into rw from test1 where rownum < 100 ;
       
       forall i in rw.first .. rw.last save exceptions
          insert into test1 values rw(i);
    exception when others then
       null;

    end;

    otis.runstats_pkg.rs_middle;

    declare

      type row_type is table of test1%rowtype;
      rw row_type;
    begin
       select id+10000, value bulk collect into rw from test1 where rownum < 100;
       
       forall i in rw.first .. rw.last save exceptions
          insert into test1 values rw(i);
    exception when others then
       null;

    end;

    otis.runstats_pkg.rs_stop;
end;
/

• results --
  /*
  Run1 ran in 12 hsecs Run2 ran in 1 hsecs run 1 ran in 1200% of the time

Name                                Run1      Run2      Diff
-- skip
LATCH.library cache pin            1,051        12    -1,039
LATCH.library cache                1,068        13    -1,055
STAT...recursive calls             1,392         5    -1,387
STAT...session logical reads       2,075       538    -1,537
LATCH.cache buffers chains         6,238     2,633    -3,605
STAT...redo size                 192,772    69,524  -123,248
STAT...session pga memory        131,072         0  -131,072
        

Run1 latches total versus runs -- difference and pct
      Run1      Run2      Diff     Pct
    10,063     3,456    -6,607 291.17%

*/

-- 
 Edgar                            

----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request_at_freelists.org
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

Received on Wed Mar 31 2004 - 10:31:40 CST