Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: fluctuating execution times

Re: fluctuating execution times

From: Thomas Kyte <tkyte_at_us.oracle.com>
Date: 7 Jan 2002 16:30:23 -0800
Message-ID: <a1deiv039j@drn.newsguy.com> 





In article <Afn_7.7391$6q2.1873936_at_news2-win.server.ntlworld.com>, "Keith
says...


>

>I missed the reference to an index being present.

>




I don't think there was one -- I made that up.  I just wanted to show that
SIZABLE redo could be generated by such a simple example, much much more then
8k.



Even without the index however (just to be fair), the results are:



redo size =       16,868                    1,000 rows in a statement.


PL/SQL procedure successfully completed.
 

redo size =      245,152                    1,000 rows, one at a time.


PL/SQL procedure successfully completed.


redo size =      599,756                    1,000 rows with a commit after each


PL/SQL procedure successfully completed.





>"Thomas Kyte" <tkyte_at_us.oracle.com> wrote in message

>news:a1ccj902cs_at_drn.newsguy.com...

>> In article <Pfb_7.5309$wd1.655718_at_news11-gui.server.ntli.net>, "Keith

>says...

>> >

>> >Could it not be the acquisition of a new initialised block  / acquisition

>of

>> >transaction entry in the block etc.?

>>

>> doubt it.

>>

>> >

>> >The values being inserted are three zeroes, which at about 2 bytes each

>plus

>> >a 1 byte row header, plus a little block overhead would workout at around

>> >1000 rows per 8k block. If you could fit just a little more than this in

>the

>> >block, and block acquisition was significant, you might get the behaviour

>> >observed.

>> >

>> >I don't think the redo logs would be as small as 8K!

>>

>> three columns, one index (and not knowing about anything else) and the

>redo

>> would be 64k or so for a SINGLE insert with 1,000 rows, it will be 1/2meg

>if you

>> insert 1000 rows INDIVIDUALLY and closer to 1meg if you insert 1000 rows

>and

>> commit each one -- you never know.  I've seen worse...

>>

>>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> create table t ( x int, y int, z int );

>>

>> Table created.

>>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> create index t_idx on t(x);

>>

>> Index created.

>>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> set serveroutput on

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> declare

>>   2          begin_value number;

>>   3          end_value number;

>>   4  begin

>>   5      select b.value into begin_value

>>   6        from v$statname a, v$mystat b

>>   7       where a.statistic# = b.statistic#

>>   8         and a.name = 'redo size'

>>   9         and b.value > 0;

>>  10

>> 11     insert into t select '0', '0', '0' from all_objects where rownum <=

>1000;

>>  12

>>  13      select b.value-begin_value into end_value

>>  14        from v$statname a, v$mystat b

>>  15       where a.statistic# = b.statistic#

>>  16         and a.name = 'redo size'

>>  17         and b.value > 0;

>>  18

>> 19          dbms_output.put_line( 'redo size = ' ||

>> to_char(end_value,'999,999,999') );

>>  20  end;

>>  21  /

>> redo size =       60,488

>>

>> PL/SQL procedure successfully completed.

>>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> declare

>>   2          begin_value number;

>>   3          end_value number;

>>   4  begin

>>   5      select b.value into begin_value

>>   6        from v$statname a, v$mystat b

>>   7       where a.statistic# = b.statistic#

>>   8         and a.name = 'redo size'

>>   9         and b.value > 0;

>>  10

>>  11     for i in 1 .. 1000

>>  12     loop

>>  13          insert into t values ( '0', '0', '0' );

>>  14     end loop;

>>  15

>>  16

>>  17      select b.value-begin_value into end_value

>>  18        from v$statname a, v$mystat b

>>  19       where a.statistic# = b.statistic#

>>  20         and a.name = 'redo size'

>>  21         and b.value > 0;

>>  22

>> 23          dbms_output.put_line( 'redo size = ' ||

>> to_char(end_value,'999,999,999') );

>>  24  end;

>>  25  /

>> redo size =      489,696

>>

>> PL/SQL procedure successfully completed.

>>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM>

>> ops$tkyte_at_ORA817DEV.US.ORACLE.COM> declare

>>   2          begin_value number;

>>   3          end_value number;

>>   4  begin

>>   5      select b.value into begin_value

>>   6        from v$statname a, v$mystat b

>>   7       where a.statistic# = b.statistic#

>>   8         and a.name = 'redo size'

>>   9         and b.value > 0;

>>  10

>>  11     for i in 1 .. 1000

>>  12     loop

>>  13          insert into t values ( '0', '0', '0' );

>>  14          commit;

>>  15     end loop;

>>  16

>>  17

>>  18      select b.value-begin_value into end_value

>>  19        from v$statname a, v$mystat b

>>  20       where a.statistic# = b.statistic#

>>  21         and a.name = 'redo size'

>>  22         and b.value > 0;

>>  23

>> 24          dbms_output.put_line( 'redo size = ' ||

>> to_char(end_value,'999,999,999') );

>>  25  end;

>>  26  /

>> redo size =      893,744

>>

>> PL/SQL procedure successfully completed.

>>

>>

>>

>>

>>

>>

>> >

>> >"Thomas Kyte" <tkyte_at_us.oracle.com> wrote in message

>> >news:a1a3ha01mhm_at_drn.newsguy.com...

>> >> In article <a19ov5$p3sst$1_at_ID-54600.news.dfncis.de>, "Steffen says...

>> >> >

>> >> >

>> >> >"Thomas Kyte" <tkyte_at_us.oracle.com> wrote in message

>> >> >news:a17h6c02fqq_at_drn.newsguy.com...

>> >> >> In article <a17bh5$m5jr8$1_at_ID-54600.news.dfncis.de>, "Steffen

>says...

>> >> >> >

>> >> >> >i execute a stmt 1000 times in 10 loops against a oracle 8.0.5, but

>> >the

>> >> >> >execution time fluctuates dramatic

>> >> >> >i have no clue why

>> >> >> >

>> >> >>

>> >> >> are you working in a dust free lab with your own network, no other

>> >users?

>> >> >

>> >> >yap

>> >> >

>> >> >> Is the database a single user database?

>> >> >

>> >> >yap

>> >> >

>> >> >> is the server a single user server?

>> >> >

>> >> >yap

>> >> >

>> >> >> is the network free from all other traffic?

>> >> >

>> >> >yap

>> >> >

>> >> >

>> >> >> If not, everything will flucuate.

>> >> >>

>> >> >> Although, based on the pattern I see below (fast, slow, fast, slow,

>> >fast,

>> >> >slow

>> >> >> or fast, fast, slow, fast, fast, slow and so on) -- it could very

>well

>> >be

>> >> >that

>> >> >> your redo logs are undersized, your alert log is full of "cannot

>> >allocate

>> >> >new

>> >> >> log" and you are seeing the system pause while a checkpoint or

>archival

>> >> >> completes.

>> >> >>

>> >> >> Review your alert log.  Use things like STATSPACK and

>TKPROF/SQL_TRACE


>> >to

>> >> >> diagnose performance releated issues.

>> >> >

>> >> >

>> >> >i'll check this out, but.. if it would be the redo log shouldn't it be

>> >same

>> >> >same for all tests, because redos depend on the amount of inserted

>rows

>> >> >

>> >>

>> >> It does apppear to be the same for all tests.

>> >>

>> >> fast, slow, fast, slow, fast, slow = 1000 rows inserted.

>> >>

>> >> fast, fast, slow, fast, fast, slow, fast, fast, slow = 333 rows

>inserted.

>> >>

>> >>

>> >> slow, slow, slow, slow, slow = not using prepared statements so you

>burnt

>> >so

>> >> many CPU cycles parsing, the IO didn't count anymore (it had a chance

>to

>> >catch

>> >> up all on its own).

>> >>

>> >>

>> >> Looks like you fit maybe about 1,000 rows into the redo logs before

>> >wrapping and

>> >> then wait for a checkpoint to complete.  Looks fairly consistent.

>> >>

>> >> >>

>> >> >> >i thought:

>> >> >> >allocating extends takes times - no it seems to be another thing,

>coz

>> >it

>> >> >> >does depends on the number of rows how offen the exec. time

>fluctuates

>> >> >> >lazy writer?

>> >> >> >other?

>> >> >> >

>> >> >> >damned!!! plz help :-)

>> >> >> >

>> >> >> >

>> >> >> >Oracle JDBC driver

>> >> >> >batchsupport: true

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 4997 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 6449 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 4106 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 6249 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 4106 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 6319 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 4206 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 6800 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 4427 ms

>> >> >> >1) 1000 unprepared stmts: insert into BatchTest (c1, c2, c3) values

>> >> >> >('0','0',0) : 6589 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 4476 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 6630 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 4497 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 6970 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 4527 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 6920 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 4587 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 6669 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 4616 ms

>> >> >> >2) single unprepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0) : 7571 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >2794 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >5468 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >2654 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >4787 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >2634 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >4907 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >2664 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >4907 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >2654 ms

>> >> >> >4) 1000 prepared stmts: insert into BatchTest (c1, c2, c3) values

>(?,

>> >?,

>> >> >?):

>> >> >> >5007 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1632 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1633 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 3936 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1592 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1593 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 3915 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1582 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1813 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 2764 ms

>> >> >> >5) 333 prepared stored proc calls: { call BT1 (?,?,?) }: 1602 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 110 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 90 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 180 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 80 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 90 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 90 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 90 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 90 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 331 ms

>> >> >> >7) single prepared jdbc batch with 1000 stmts: insert into

>BatchTest

>> >(c1,

>> >> >> >c2, c3) values (?, ?, ?): 140 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1862 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1642 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 4106 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1643 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1652 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 3915 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1903 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1703 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 4176 ms

>> >> >> >8) single prepared jdbc batch with 333 stored proc calls: { call

>BT1

>> >> >> >(?,?,?) }: 1693 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >921 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >330 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >781 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >620 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >340 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >340 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >952 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >491 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >330 ms

>> >> >> >6) single unprepared sql batch with 333 stored proc calls:

>> >> >BT1('0','0',0); :

>> >> >> >331 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4677 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4426 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4396 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4377 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4436 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4707 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4366 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4427 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4426 ms

>> >> >> >3) single unprepared sql batch with 1000 stmts: insert into

>BatchTest

>> >> >(c1,

>> >> >> >c2, c3) values ('0','0',0); : 4747 ms

>> >> >> >

>> >> >> >

>> >> >> >

>> >> >>

>> >> >> --

>> >> >> Thomas Kyte (tkyte_at_us.oracle.com)

>http://asktom.oracle.com/

>> >> >> Expert one on one Oracle, programming techniques and solutions for

>> >Oracle.

>> >> >> http://www.amazon.com/exec/obidos/ASIN/1861004826/

>> >> >> Opinions are mine and do not necessarily reflect those of Oracle

>Corp

>> >> >>

>> >> >

>> >> >

>> >>

>> >> --

>> >> Thomas Kyte (tkyte@us.oracle.com)             http://asktom.oracle.com/

>> >> Expert one on one Oracle, programming techniques and solutions for

>Oracle.

>> >> http://www.amazon.com/exec/obidos/ASIN/1861004826/

>> >> Opinions are mine and do not necessarily reflect those of Oracle Corp

>> >>

>> >

>> >

>>

>> --

>> Thomas Kyte (tkyte@us.oracle.com)             http://asktom.oracle.com/

>> Expert one on one Oracle, programming techniques and solutions for Oracle.

>> http://www.amazon.com/exec/obidos/ASIN/1861004826/

>> Opinions are mine and do not necessarily reflect those of Oracle Corp

>>

>

>



--
Thomas Kyte (tkyte@us.oracle.com)             http://asktom.oracle.com/ 
Expert one on one Oracle, programming techniques and solutions for Oracle.
http://www.amazon.com/exec/obidos/ASIN/1861004826/  
Opinions are mine and do not necessarily reflect those of Oracle Corp 


Received on Mon Jan 07 2002 - 18:30:23 CST












Original text of this message













  HOME |
  ASK QUESTION |
  ADD INFO |
  SEARCH |
  E-MAIL US