Skip to Main Content

Breadcrumb

May 4th

Question and Answer

Tom Kyte

Thanks for the question.

Asked: May 25, 2002 - 8:40 pm UTC

Last updated: May 11, 2009 - 4:53 pm UTC

Version: 8.1.6

Viewed 50K+ times! This question is

You Asked

Tom

1.Set timing on in sql plus show a figure like 56430 , what does that mean. How much time does it represent?


2.I dont want to use set timing on , and using tkprof means spending 10 hours for the dba to mail me the trace file.

I want to know how can I use dbms_utility from sqlplus and set some variables, then execute a query and see how much time it has taken to execute .

How should I do it.

or let me put it this way what is the best way to find out how much time a sql is taking using dbms_utility from sql plus.

Thansks a lot.

and Tom said...

1) you have an OLD version of sqlplus on windows. It is hundreds of seconds.

2)

set serveroutput on
variable n number
exec :n := dbms_utility.get_time;
select ......
exec dbms_output.put_line( (dbms_utility.get_time-:n)/100) || ' seconds....' );

If you just get the version of sqlplus that goes with your database -- 816 -- it'll do the "right thing"



Rating

  (21 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

can set autotrace on trace only

Vasaku, May 25, 2002 - 11:53 pm UTC

get me only the time , without executing the query

Because when we execute the query in sql plus the resultant time will include the time of the screen output also.

will set autotrace on trace only , do the trick for me( as I told you above I cannot use set timing on or sql_trace, for the given reasons)

Tom Kyte
May 26, 2002 - 10:37 am UTC

I think you mean "without PRINTING the query results".

set autotrace traceonly -- runs the query, fetches the rows and prints the stats but not the row data.

set autotrace traceonly explain -- just does an explain plan for SELECTS, does not execute them (but would be useless for timing).

autotrace adds some overhead of its own -- so beware, it can add LOTS of time to the timings (querying v$ tables can be slow and that is what it does).


You can also use set termout off/on before/after the query to surpress the display.


if it takes 10 hours...

A reader, May 26, 2002 - 7:33 am UTC

to get the tkprof output, its a time for a new dba

so this script should give me reasonably accurate time using sqlplus

Vasaku, May 26, 2002 - 11:02 am UTC

set serveroutput on
set termout off
variable n number
exec :n := dbms_utility.get_time;
select ......
exec dbms_output.put_line( (dbms_utility.get_time-:n)/100) || ' seconds....' );

set termout off


But , I dont think 'exec :n := dbms_utility.get_time;
', is a valid statement from within a sql script.

Your opinion please.( what I'm trying to arrive at a is a simple solution for the said task from sqlplus)



Tom Kyte
May 26, 2002 - 11:21 am UTC

It needs no opinion.  It definitely works (i would not have suggested it otherwise)


take a script like this:

set echo on
variable n number
exec :n := dbms_utility.get_time
set termout off
select * from all_users;
set termout on
exec dbms_output.put_line( ((dbms_utility.get_time-:n)/100) || ' seconds...' );

and it'll do this:

ops$tkyte@ORA817DEV.US.ORACLE.COM> variable n number
ops$tkyte@ORA817DEV.US.ORACLE.COM> exec :n := dbms_utility.get_time

PL/SQL procedure successfully completed.

ops$tkyte@ORA817DEV.US.ORACLE.COM> set termout off
ops$tkyte@ORA817DEV.US.ORACLE.COM> exec dbms_output.put_line( ((dbms_utility.get_time-:n)/100) || ' seconds...' );
.02 seconds...

PL/SQL procedure successfully completed.

Note that termout off will not 100% remove the "print" overhead as sqlplus still goes through the steps to format -- it just doesn't print it on screen.  Whether that is faster or slower then set autotrace traceonly depends on how active your system is (and hence how slow the v$ queries are) and the volumn of data. 

but termout off still showing the output

A reader, May 29, 2002 - 9:20 am UTC

Tom, I expect termout off not to show the output but look at the following

SQL> set termout off
SQL> select 'x' from dual;

'
-
x

why is this so?

As I see you have stated that this setting will suppress output. 

Tom Kyte
May 29, 2002 - 9:32 am UTC

You need to run it in a script.


ops$tkyte@ORA817DEV.US.ORACLE.COM> set termout off
ops$tkyte@ORA817DEV.US.ORACLE.COM> select * from dual;

D
-
X

ops$tkyte@ORA817DEV.US.ORACLE.COM> set termout on
ops$tkyte@ORA817DEV.US.ORACLE.COM> !cat test.sql
set termout off
select * from dual;
set termout on

ops$tkyte@ORA817DEV.US.ORACLE.COM> @test
ops$tkyte@ORA817DEV.US.ORACLE.COM> 



All interactively typed commands will always display on screen. 

How to read Elapsed time reported by sql*plus

Steve, December 26, 2002 - 10:24 am UTC

Hi Tom,

I just ran very long query after I set timing on
I got the following

Elapsed: 09:593:35598.00

Is that 8 hours 593 min 35598 sec? I am using 8.1.7 sql*plus

Thanks!

Steve

Tom Kyte
December 26, 2002 - 11:55 am UTC

sqlplus set timing is "broken" occasionally -- especially in windows.  

I don't know what time that might be....

tkprof is the best way to time.

SQL> set time on

would be good as well (the prompt will contain the time, you can always do the math yourself after that)

 

gree China, March 07, 2003 - 5:22 pm UTC

TOM,

If I count the time for a sql script with a spool command , how to remove the the time message in the tail of the spooled target file.

Thanks!

Tom Kyte
March 07, 2003 - 7:29 pm UTC

don't use set timing on.

Do this instead:


variable n number
exec :n := dbms_utility.get_time
spool ....
.....
spool off
begin
dbms_output.put_line
( (round((dbms_utility.get_time - :n)/100,2)) || ' seconds' );
end;
/



How reliable is set timing on.

A reader, April 16, 2003 - 1:05 am UTC

Hi tom,

Wanted to know how reliable is set timing on. Say i'm running two different select statements on a table for the same set of results. Will the timing on result (alone) justify which select statement is better?

Is it possible that the SQL timing shows the first select statement to be faster but when i see the tkprof result i see that the second select statement is faster (measuring the CPU and elapsed time) than the first one ?

Thanks and Regards

Tom Kyte
April 16, 2003 - 10:07 am UTC

not at all. tkprof is the ONLY tool to use to see what query is "better".

looking for CPU time
looking for logical io's.


timing on in sqlplus times how fast your client machine happened to be at that instant as much as it times how fast the server was.


tkprof is the source of truth.
timing on is good for very little.

Thanks a lot TOM

A reader, April 16, 2003 - 10:35 am UTC


Arraysize ?

sush, April 16, 2003 - 10:54 am UTC

I think the arraysize(default is 15) in sqlplus make a difference in query output apart from set termout on ...

How do we set the arraysize in plsql(ofcourse in sqlplus we can say set arraysize = 1000 or so )..

Tom Kyte
April 16, 2003 - 11:03 am UTC


fetch c bulk collect into ... limit N;

for selects (look up bulk collect) and


forall i in 1 .. N
DML_statement

for modifications.

set timing on

vinodhps, June 21, 2003 - 9:56 am UTC

Hi .. tom,
In most of you answers you get that Elapsed: "time".
how are you getting that...
iam using oracle 9i ..
set timing on command gives me.. real:"timing".
can you please tell me that..
thanks

Tom Kyte
June 21, 2003 - 10:36 am UTC

you are using oracle9i the database but apparently you are using sqlplus 8.something on windows as your client.

it is your sqlplus version.

Thanks

vinodhps, June 22, 2003 - 9:41 am UTC

Thanks tom,
Yes iam still using.. sql 8 version..
thanks..


A reader, August 08, 2004 - 1:41 am UTC

Tom,

In addition to the above example you have given for getting the number of seconds...I am eager to know how to get "HOURS" & "MINUTES" along with "SECONDS" using DBMS_UTILITY.Get_Time function.

Rgrds

Tom Kyte
August 08, 2004 - 9:57 am UTC

you "divide" and "trunc" lots -- just math


dbms_utility.get_time gives you a "ticker" in hundredths of seconds.

so, you get a start and a stop.  you subtract them.

Now you have hundreds of seconds.

then if you mod that, you have hundreds of seconds.
divide by 100 and you have seconds.
divide that by 60 divided by 60, trunc and you have hours 
and so on.

there are many ways to do this, this was my first thought:

ops$tkyte@ORA9IR2> exec :x := 123456789
 
PL/SQL procedure successfully completed.
 
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> select hours, mins, trunc(secs-mins*60-hours*60*60) secs, hundredths
  2    from (
  3  select hours, trunc(secs/60-hours*60) mins, secs, hundredths
  4    from (
  5  select trunc(:x/100/60/60) hours,
  6         trunc(:x/100) secs,
  7         mod(:x,100) hundredths
  8    from dual
  9         )
 10         )
 11  /
 
     HOURS       MINS       SECS HUNDREDTHS
---------- ---------- ---------- ----------
       342         56          7         89
 
ops$tkyte@ORA9IR2>
ops$tkyte@ORA9IR2> exec :x := ((55*60*60)+(47*60)+(32))*100 + 22
 
PL/SQL procedure successfully completed.
 
ops$tkyte@ORA9IR2> /
 
     HOURS       MINS       SECS HUNDREDTHS
---------- ---------- ---------- ----------
        55         47         32         22
 

reader

A reader, February 08, 2005 - 10:12 am UTC

If the output of a SQL query is very large, is there a
way to spool to /dev/null and setting termout off,
however if there is any ORA- error to see it on the screen

Tom Kyte
February 09, 2005 - 1:19 am UTC

set autotrace traceonly
big_query
set autotrace off


that'll run the query, not print the results and if any errors, they will be there.

Reader

A reader, February 09, 2005 - 2:07 pm UTC

Will it catch runtime kernal errors like

Error: ORA-3232 Text: unable to allocate an extent of %s blocks from tablespace %s --------------------------------------------------------------------------- Cause: An attempt was made to specify a HASH_MULTIBLOCK_IO_COUNT value that is greater than the tablespace's NEXT value Action: Increase the value of NEXT for the tablespace using ALTER TABLESPACE DEFAULT STORAGE or decrease the value of HASH_MULTIBLOCK_IO_COUNT.

Tom Kyte
February 09, 2005 - 3:20 pm UTC

it'll show any error, there is no "/dev/null" involved here.

A reader, June 08, 2005 - 5:03 pm UTC

Hi Tom,

After executing a query; I am getting this timestamp: Elapsed: 00:00:01.04

Does this mean 1sec, 4msec?

I am using the following version of oracle database:

Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
PL/SQL Release 9.2.0.6.0 - Production
CORE 9.2.0.6.0 Production
TNS for Solaris: Version 9.2.0.6.0 - Production
NLSRTL Version 9.2.0.6.0 - Production

Thanks.

Tom Kyte
June 08, 2005 - 10:10 pm UTC

1 and 4/100th of a second.

A reader, June 09, 2005 - 12:39 pm UTC

Thanks a lot Tom!

Elapsed on windows 8.1.7 still "broken"? (unpatched)

CG, July 20, 2006 - 2:18 pm UTC

Tom, I have 8.1.7 SQL Plus and 9.2.0.7 db 64bit

is the belowed elapsed time still "wacked"?

I read 1 minute 86 seconds?????

SQL> select soh.id_str_rt,
  2        soh.id_itm,
  3        itm.de_itm,
  4        itm.lu_uom_dft,
  5        itmloc.id_spr,
  6        ris.vpn,
  7        itmloc.repn_type,
  8        soh.total_quantity,
  9        soh.in_transit_quantity,
 10        soh.adjust_unavail_qty
 11  from   rk_store_item_soh soh,
 12        as_itm itm,
 13         as_itm_rtl_str itmloc,
 14         rk_item_supplier ris
 15  where itmloc.id_itm = itm.id_itm
 16  and itmloc.id_itm = ris.id_itm
 17  and itmloc.id_spr = ris.id_spr
 18  and soh.id_itm = itmloc.id_itm
 19  and soh.id_str_rt = itmloc.id_str_rt
 20  and soh.id_str_rt = '10';

2136694 rows selected.

Elapsed: 00:01:86.34

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=490 Card=1311745 Byt
          es=684730890)

   1    0   TABLE ACCESS (FULL) OF 'DIS_MV' (Cost=490 Card=1311745 Byt
          es=684730890)





Statistics
----------------------------------------------------------
         23  recursive calls
          0  db block gets
     150011  consistent gets
       8018  physical reads
          0  redo size
   91748375  bytes sent via SQL*Net to client
    5413203  bytes received via SQL*Net from client
     142448  SQL*Net roundtrips to/from client
          8  sorts (memory)
          0  sorts (disk)
    2136694  rows processed 

Tom Kyte
July 22, 2006 - 5:05 pm UTC

it was a sqlplus'ism - the database version was never relevant.

that looks funny - but I would not suggest using 8i sqlplus either. I have not personally observed that

set timing on and DDL

mohan, January 05, 2007 - 7:31 pm UTC

Oracle 9i release 2 on unix

Hi Tom,
I am trying to time some DDL (alter table move tablespace)
statements...to get timing estimates before doing it in production database..
so you can just do

set timing on
alter table move..
alter index move..
...

set timing on is per statement correct...not cumulative time?

Thanks
Tom Kyte
January 06, 2007 - 10:56 am UTC

set timing on will cause sqlplus to print out the amount of time the last SQL statement it executed consumed. It is not cumulative, and it does not count "idle time" (unless you have pause on and page through a query slowly that is)

set timing on and DDL

mohan, January 05, 2007 - 7:33 pm UTC

Oracle 9i release 2 on unix

Hi Tom,
I am trying to time some DDL (alter table move tablespace)
statements...to get timing estimates before doing it in production database..
so you can just do

set timing on
alter table move..
alter index move..
...

set timing on is per statement correct...not cumulative time?

Thanks

Set Timing on Format

A reader, May 10, 2009 - 4:40 am UTC

Hi Tom,
What is the format of elapsed time shown through set timing on sqlplus command after seconds:

00:00:00:20 -> Is 20 centisecond?

Regards,
Tom Kyte
May 11, 2009 - 4:53 pm UTC

Elapsed: 00:00:00.01


that is 1/100th of a second


Elapsed: 00:00:00.10

that would be 1/10th of a second.

Set timing on

Vikas Atrey, April 12, 2012 - 3:20 am UTC

In the earlier reported displayed time as below it looks like elapsed time is correct but just the dispay is not very right.

Elapsed: 09:593:35598.00

i.e. 35598/3600==593/60=9.88833333333333

So it is saying that total elapsed time was 9.88 hours i.e. 9 hours 53 minutes and 18 seconds


More to Explore

DBMS_UTILITY

More on PL/SQL routine DBMS_UTILITY here