Oracle FAQ | Your Portal to the Oracle Knowledge Grid |
Home -> Community -> Usenet -> c.d.o.server -> Re: dbms_profiler incorect timing info?
In article <7vo8huglu1s7esus9s1fpfmcvog4ke9cq1_at_4ax.com>, DazzaL says...
>
>Hi,
>
>im testing out dbms_profiler but the timings it coming back with appear =
>wrong:
>
>the package im testing.......
>
>CREATE OR REPLACE package one as
>
> procedure main;
>
>end;
>/
>CREATE OR REPLACE package body one as
> procedure main
> as
> begin
> for i in (select * from all_objects)
> loop
> two.main;
> end loop;
> end main;
>end;
>/
>
>CREATE OR REPLACE package two as
> procedure main;
>end;
>/
>CREATE OR REPLACE package body two as
> procedure main
> as
> v_temp varchar2(2000);
> begin
> select 'x' into v_temp from dual;
> end main;
>end;
>/
>
>
>the script t collect data:
>
>set serveroutput on size 1000000;
>set timing on;
>set linesize 200;
>
>declare
> v_run number;
>begin
> dbms_profiler.start_profiler('test','',v_run);
> one.main;
> dbms_profiler.stop_profiler;
> dbms_profiler.rollup_run(v_run);
> prof_report_utilities.print_run(v_run);
>end;
>/
>
>the timings it comes back with are =20
>
>=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
>=3D=3DResults for run #8 made on 22-JUN-02 12:51:29 =
>=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
>(test) Run total time: 1811.39 seconds
>Unit #1: <anonymous>.<anonymous> - Total time: .03 seconds
>Unit #2: SPG.ONE - Total time: 1038.55 seconds
>1 package body one as
>2
>3
>4 procedure main
>5 as
>6
>7 v_temp varchar2(2000);
>8 begin
>9
>10 21,242 996.28314 .04690156 for i in (select * =
>from all_objects)
>11 loop
>12
>13 42,483 42.258235 .00099470 two.main;
>14 end loop;
>15
>16 1 .00634494 .00634494 end main;
>17 end;
>Unit #3: SPG.TWO - Total time: 693.64 seconds
>1 package body two as
>2
>3
>4 procedure main
>5 as
>6
>7 v_temp varchar2(2000);
>8 begin
>9
>10 21,241 672.91691 .03168009 select 'x' into =
>v_temp from dual;
>11
>12 21,241 20.724036 .00097566 end main;
>13 end;
>
>PL/SQL procedure successfully completed.
>
>Elapsed: 00:00:04.78
>SQL>=20
>
>
>so why does dbms_profiler say that the total run time is : (test) Run =
>total time: 1811.39 seconds
>when it clearly took only 4.78 seconds in total=20
>
>Thanks.
>
>--=20
>Daz.
sigh, never a version in sight. Oh well, anyway -- cannot reproduce:
===========================Results for run #1 made on 22-JUN-02 14:14:10 ========================= (test) Run total time: 11.07 seconds Unit #1: SYS.DBMS_PROFILER - Total time: .00 seconds Unit #2: <anonymous>.<anonymous> - Total time: .04 seconds Unit #3: OPS$TKYTE.ONE - Total time: 6.57 seconds 1 package body one as 2 procedure main 3 as 4 begin 5 20,326 6.3901402 .00031438 for i in (select * from all_objects) 6 loop 7 40,651 .17824309 .00000438 two.main; 8 end loop; 9 1 .00003304 .00003304 end main; 10 end; Unit #4: OPS$TKYTE.TWO - Total time: 4.08 seconds 1 package body two as 2 procedure main 3 as 4 v_temp varchar2(2000); 5 begin 6 20,325 4.0253407 .00019804 select 'x' into v_temp from dual; 7 20,325 .05463537 .00000268 end main; 8 end;
PL/SQL procedure successfully completed.
Elapsed: 00:00:11.57
ops$tkyte_at_ORA817DEV.US.ORACLE.COM>
ops$tkyte_at_ORA817DEV.US.ORACLE.COM> select * from v$version;
BANNER
-- Thomas Kyte (tkyte@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 CorpReceived on Sat Jun 22 2002 - 13:20:35 CDT