Skip to Main Content

Breadcrumb

May 4th

Question and Answer

Chris Saxon

Thanks for the question.

Asked: January 31, 2017 - 7:51 am UTC

Last updated: June 06, 2018 - 10:58 am UTC

Version: 11g

Viewed 10K+ times! This question is

You Asked

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.2
CPU : 12 - type 8664, 6 Physical Cores
Process Affinity : 0x0x0000000000000000
Memory (Avail/Total): Ph:3920M/8095M, Ph+PgF:3147M/11935M
Instance name: bwdev
Redo thread mounted by this instance: 1
Oracle process number: 45
Windows thread id: 7904, image: ORACLE.EXE (SHAD)


*** 2017-01-31 12:56:01.921
*** SESSION ID:(1145.1867) 2017-01-31 12:56:01.921
*** CLIENT ID:() 2017-01-31 12:56:01.921
*** SERVICE NAME:(bwdev) 2017-01-31 12:56:01.921
*** MODULE NAME:(TOAD 12.10.0.30) 2017-01-31 12:56:01.921
*** ACTION NAME:() 2017-01-31 12:56:01.921

WAIT #447645104: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672955261
WAIT #447645104: nam='SQL*Net message from client' ela= 655 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672957113
CLOSE #447645104:c=0,e=20,dep=0,type=1,tim=17672957187
=====================
PARSING IN CURSOR #447648520 len=23 dep=0 uid=97 oct=3 lid=97 tim=17672963025 hv=2980445538 ad='7ffc07556f78' sqlid='4sxqyhusubzb2'
select * from emp
END OF STMT
PARSE #447648520:c=0,e=5799,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4171842832,tim=17672963024
WAIT #447648520: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672963151
WAIT #447648520: nam='SQL*Net message from client' ela= 1868 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672965098
CLOSE #447648520:c=0,e=10,dep=0,type=0,tim=17672965161
=====================
PARSING IN CURSOR #447648520 len=23 dep=0 uid=97 oct=3 lid=97 tim=17672965272 hv=2980445538 ad='7ffc07556f78' sqlid='4sxqyhusubzb2'
select * from emp
END OF STMT
PARSE #447648520:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4171842832,tim=17672965271
EXEC #447648520:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4171842832,tim=17672965375
WAIT #447648520: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672965443
WAIT #447648520: nam='SQL*Net more data to client' ela= 71 driver id=1413697536 #bytes=8154 p3=0 obj#=104 tim=17672965768
WAIT #447648520: nam='SQL*Net more data to client' ela= 57 driver id=1413697536 #bytes=8136 p3=0 obj#=104 tim=17672966096
WAIT #447648520: nam='SQL*Net more data to client' ela= 45 driver id=1413697536 #bytes=8145 p3=0 obj#=104 tim=17672966382
WAIT #447648520: nam='SQL*Net more data to client' ela= 44 driver id=1413697536 #bytes=8146 p3=0 obj#=104 tim=17672966665
WAIT #447648520: nam='SQL*Net more data to client' ela= 43 driver id=1413697536 #bytes=8145 p3=0 obj#=104 tim=17672966932
WAIT #447648520: nam='SQL*Net more data to client' ela= 50 driver id=1413697536 #bytes=8145 p3=0 obj#=104 tim=17672967216
WAIT #447648520: nam='SQL*Net more data to client' ela= 42 driver id=1413697536 #bytes=8144 p3=0 obj#=104 tim=17672967485
WAIT #447648520: nam='SQL*Net more data to client' ela= 43 driver id=1413697536 #bytes=8147 p3=0 obj#=104 tim=17672967759
WAIT #447648520: nam='SQL*Net more data to client' ela= 45 driver id=1413697536 #bytes=8145 p3=0 obj#=104 tim=17672968044
WAIT #447648520: nam='SQL*Net more data to client' ela= 44 driver id=1413697536 #bytes=8143 p3=0 obj#=104 tim=17672968325
FETCH #447648520:c=0,e=2959,p=0,cr=43,cu=1,mis=0,r=501,dep=0,og=1,plh=4171842832,tim=17672968461
WAIT #447648520: nam='SQL*Net message from client' ela= 661 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672969166
=====================
PARSING IN CURSOR #447645104 len=69 dep=0 uid=97 oct=42 lid=97 tim=17672969236 hv=3164292706 ad='0' sqlid='8r8b2pyy9qjm2'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
PARSE #447645104:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=17672969235
EXEC #447645104:c=0,e=871,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=17672970172
WAIT #447645104: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672970230
WAIT #447645104: nam='SQL*Net message from client' ela= 19096 driver id=1413697536 #bytes=1 p3=0 obj#=104 tim=17672989406
CLOSE #447645104:c=0,e=4,dep=0,type=3,tim=17672989496
=====================
PARSING IN CURSOR #453796016 len=55 dep=0 uid=97 oct=42 lid=97 tim=17672989608 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #453796016:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=17672989607
EXEC #453796016:c=0,e=750,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=17672990426



Now I do not know what is like below :-
WAIT ,nam, ela, driver id, #bytes, p3, obj#, tim,CLOSE and so many keyword inside trace file.
so how can i understand?

and Chris said...

Rather than try and read the raw trace file, in most cases I'd use tkprof to parse the output. This summarizes the data, showing you how long each statement took to do its parsing, execution and fetching. And details about the plan and waits if you captured these.

To use this, run:

tkprof tracefile.trc output.txt


There are a number of options for sorting this output:

http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94985

For details on understanding this, read

http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94992

Or you can open them in SQL Developer and it'll give you tkprof like output.

Rating

  (1 rating)

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

Comments

View the contents of trace file

Srikanth, June 06, 2018 - 7:45 am UTC

Hi,

I am trying to view the contents of trace file. Please find the below:

[oracle@azdwcma304 trace]$ tkprof stgt_dw00_62439.trc stgt_dw00_62439.prf

TKPROF: Release 12.1.0.2.0 - Development on Wed Jun 6 07:30:21 2018

Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.


[oracle@azdwcma304 trace]$ cat stgt_dw00_62439.prf

TKPROF: Release 12.1.0.2.0 - Development on Wed Jun 6 07:30:21 2018

Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.

Trace file: stgt_dw00_62439.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
Trace file: stgt_dw00_62439.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
0 user SQL statements in trace file.
0 internal SQL statements in trace file.
0 SQL statements in trace file.
0 unique SQL statements in trace file.
38 lines in trace file.
0 elapsed seconds in trace file.

the above output is not displaying the error information. Can you please suggest a way to read the actual error information.


Thanks,
Srikanth
Chris Saxon
June 06, 2018 - 10:58 am UTC

What's in the raw trace file? How did you generate it?

tkprof is only for analysing user traces you requested by setting:

alter session set sql_trace = true;


Or similar. Lots of background processes write their own trace files. Which tkprof can't interpret!

More to Explore

VLDB

If you are new to partitioning, check out Connor McDonald's introduction series here.

VLDB

Documentation set on VLDB and Partitioning.