Re: dbms_profiler incorect timing info?

From: Thomas Kyte <tkyte_at_oracle.com>
Date: 22 Jun 2002 11:20:35 -0700
Message-ID: <af2f5j015ri@drn.newsguy.com>

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

---

Oracle8i Enterprise Edition Release 8.1.7.3.0 - Production PL/SQL Release 8.1.7.3.0 - Production
CORE 8.1.7.0.0 Production
TNS for Solaris: Version 8.1.7.3.0 - Production NLSRTL Version 3.4.1.0.0 - Production

--
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 Corp 

Received on Sat Jun 22 2002 - 13:20:35 CDT