Skip to Main Content
  • Questions
  • SQL TRAce: parameter tim=nnnn, when SQL was executed

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question, Matteo.

Asked: May 09, 2005 - 10:08 am UTC

Last updated: May 09, 2005 - 10:38 am UTC

Version: 9.2.0

Viewed 1000+ times

You Asked

Can I understand when the SQL instruction was execute ?
For example "tim=1089494615008537", how can I find day, hour , minutes, seconds ?

thank you
Matteo


PARSING IN CURSOR #1 len=59 dep=0 uid=69 oct=42 lid=69 tim=1089494615008551 hv=1
879330026 ad='7e8b2eb0'
PARSE #1:c=0,e=121,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1089494615008537
EXEC #1:c=0,e=86,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1089494615008853
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 1970 p1=1413697536 p2=1 p3=0




and Tom said...

not reliably -- you can get a good "guess" by seeing the time at the top of the tracefile and subtracting. for example:

alter session set sql_trace=true;
select * from dual d1;
exec dbms_lock.sleep(5)
select * from dual d2;


now the trace file will have:


*** 2005-05-09 10:14:40.662
*** SESSION ID:(11.4450) 2005-05-09 10:14:40.661
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #3 len=32 dep=0 uid=245 oct=42 lid=245 tim=1089500078771773 hv=3943786303 ad='576def28'
alter session set sql_trace=true
END OF STMT
=====================
PARSING IN CURSOR #3 len=21 dep=0 uid=245 oct=3 lid=245 tim=1089500078773194 hv=430859874 ad='576de3bc'
select * from dual d1
END OF STMT
=====================
PARSING IN CURSOR #3 len=32 dep=0 uid=245 oct=47 lid=245 tim=1089500078883265 hv=1700220278 ad='576dd38c'
BEGIN dbms_lock.sleep(5); END;
END OF STMT
PARSE #3:c=10000,e=101446,p=7,cr=63,cu=0,mis=1,r=0,dep=0,og=4,tim=1089500078883256
EXEC #3:c=0,e=4993747,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1089500083877160
=====================
PARSING IN CURSOR #3 len=21 dep=0 uid=245 oct=3 lid=245 tim=1089500083880596 hv=379045529 ad='576ec038'
select * from dual d2
END OF STMT


taking the last tim= and the first tim=, we get:

ops$tkyte@ORA9IR2> select (1089500083880596-1089500078771773)/1000000 from dual;

(1089500083880596-1089500078771773)/1000000
-------------------------------------------
5.108823


(would be /1000 in 8i) about 5.1 seconds -- add that to:
*** SESSION ID:(11.4450) 2005-05-09 10:14:40.661

and you get 10:14:45 approximately.


as long as the tim= records are 1/1,000,000 of a second of course. could be platform specific. I was using linux




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

More to Explore

DBMS_LOCK

More on PL/SQL routine DBMS_LOCK here