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: Keith Boulton <kboulton_at_ntlunspam-world.com>
Date: Mon, 7 Jan 2002 20:12:55 -0000
Message-ID: <Afn_7.7391$6q2.1873936@news2-win.server.ntlworld.com>


I missed the reference to an index being present.

"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
>
Received on Mon Jan 07 2002 - 14:12:55 CST

Original text of this message

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