all about tracing oracle sql sessions
TRANSCRIPT
-
8/8/2019 All About Tracing Oracle SQL Sessions
1/12
HOW TO trace your own session
Platform: Oracle App:DB Ver: 9.2 App Ver:Revision
Date:
28-Nov-2005 Keywords: HOWTO, TRACE, SESSION
GoalTo trace the SQL in your own sessionFactsSolution
First, run the following commands from the SQL*Plus command prompt to switchon timed statistics and to allow for an unlimited trace file size.
alter session set timed_statistics=true
alter session set max_dump_file_size=unlimited
If you fail to set TIMED_STATISTICS=TRUE, your database kernel will emit onlyzero values instead of real durations into your trace file. If your setting ofMAX_DUMP_FILE_SIZE is too restrictive, you'll suffer the chagrin of generating amessage like the following in your trace file instead of the timing data youwanted:
*** DUMP FILE SIZE IS LIMITED TO 1048576 BYTES ***
Before starting your trace, you can modify the name of the trace file by adding aTRACEFILE_IDENTIFIER to it. You can do this by an ALTER SESSION commandsuch as what is below.
alter session set TRACEFILE_IDENTIFIER = 'something_unique';
Next comes activating the trace itself. There are several ways to do this. The old-fashioned way is to use the ALTER SESSION command as follows:
alter session set events '10046 trace name context forever, level
12'
/* code to be traced goes here */
alter session set events '10046 trace name context off'
A more elegant way to accomplish the extended SQL trace activation is to usethe DBMS_SUPPORT package:
dbms_support.start_trace(waits=>true, binds=>true)/* code to be traced goes here */
dbms_support.stop_trace()
To find the trace file, first find the directory where it is located using thefollowing:
select value from v$parameter where name = 'user_dump_dest';
-
8/8/2019 All About Tracing Oracle SQL Sessions
2/12
Then, look for a file with 'something_unique' in the filename.
HOW TO trace a 3rd party session
Platform: Oracle App:DB Ver: 9.2 App Ver:RevisionDate:
26-Oct-2006 Keywords:HOWTO, TRACE, SESSION, 3RD PARTY
GoalTo trace the SQL in 3rd party sessionFactsSolutionFirst, identify the 3rd party session to be traced. This can be cumbersome, but can be identsession has been identified make a note of the session's:
SID
Serial#
Next, run the following commands from the SQL*Plus command prompt to switch on timedstatistics and to allow for an unlimited trace file size.
alter session set timed_statistics=true
alter session set max_dump_file_size=unlimited
If you fail to set TIMED_STATISTICS=TRUE, your database kernel will emit only zero valuesinstead of real durations into your trace file. If your setting of MAX_DUMP_FILE_SIZE is toorestrictive, you'll suffer the chagrin of generating a message like the following in your trace file
instead of the timing data you wanted:
*** DUMP FILE SIZE IS LIMITED TO 1048576 BYTES ***
Before starting your trace, you can modify the name of the trace file by adding aTRACEFILE_IDENTIFIER to it. You can do this by an ALTER SESSION command such as whatis below.
alter session set TRACEFILE_IDENTIFIER = 'something_unique';
Next comes activating the trace itself. There are several ways to do this. The old-fashioned way isto use the ALTER SESSION command as follows:A more elegant way to accomplish the extended SQL trace activation is to use theDBMS_SYSTEM package:
DBMS_System.Set_Ev(sid, serial#, event, level, name);
e.g.
DBMS_System.Set_Ev(31, 97, 10046, 4,);
To find the trace file, first find the directory where it is located using the following:
-
8/8/2019 All About Tracing Oracle SQL Sessions
3/12
select value from v$parameter where name = 'user_dump_dest';
Then, look for a file with 'something_unique' in the filename.
-
8/8/2019 All About Tracing Oracle SQL Sessions
4/12
Structure of an Extended SQL Trace file
Platform: Oracle App:DB Ver: 9.2 App Ver:Revision
Date:
30-Dec-
2005
Keywords: REF, REFERENCE, TRACE FILE STRUCTURE
ReferenceFor any updates, refer to the original Metalink document Metalink:39817.1.
Introduction.between any 2 operations
This is a short reference article which summarises the output format of the rawSQL_TRACE output file. The second part of the article describes the additionaltrace lines that may be enabled by the DBMS_SUPPORT package. See MetalinkNote 62294.1 for details of this package.Note: The format may vary slightly between releases.
APPNAME mod='%s' mh=%lu act='%s' ah=%luAPPNAME Application name setting. (This only applies to Oracle 7.2
and above. This can be set by using the
DBMS_APPLICATION_INFO package. See Note 30366.1.)
mod Module name.
mh Module hash value.
act Action.
ah Action hash value.
PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=Xad='X' END OF STMT Cursor number.
len Length of SQL statement.
dep Recursive depth of the cursor.uid Schema user id of parsing user.
oct Oracle command type.
lid Privilege user id.
tim Timestamp.
Pre-Oracle9i, the times recorded by Oracle only have a
resolution of 1/100th of a second (10mS). As of Oracle9i
some times are available to microsecond accuracy
(1/1,000,000th of a second).
The timestamp can be used to determine times between points
the trace file. The value is the value in V$TIMER when the
line was written. If there are TIMESTAMPS in the file you
can use the difference between 'tim' values to determine an
absolute time.hv Hash id.
ad SQLTEXT address (see and ).
The actual SQL statement being parsed.
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d ...
http://metalink.oracle.com/metalink/plsql/ml2_documents.showDocument?p_database_id=NOT&p_id=39817.1http://metalink.oracle.com/metalink/plsql/ml2_documents.showDocument?p_database_id=NOT&p_id=39817.1 -
8/8/2019 All About Tracing Oracle SQL Sessions
5/12
PARSE ERROR In Oracle 7.2+ parse errors are reported to the trace
file.
len Length of SQL statement.
dep Recursive depth of the statement
uid User id.
oct Oracle command type (if known).
lid Privilege user id.
tim Timestamp.
err Oracle error code (e.g. ORA-XXXXX) reported
The SQL statement that errored.
If this contains a password, the statement is truncated as
indicated by '...' at the end.
PARSE #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0EXEC #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0FETCH #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0UNMAP #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
- OPERATIONS:
PARSE Parse a statement.
EXEC Execute a pre-parsed statement.
FETCH Fetch rows from a cursor.
UNMAP If the cursor uses a temporary table, when the cursor is
closed you see an UNMAP when we free up the temporary table
locks.(Ie: free the lock, delete the state object, free the
temp segment)
In tkprof, UNMAP stats get added to the EXECUTE statistics.
SORT UNMAP
As above, but for OS file sorts or TEMP table segments.
c CPU time (100th's of a second in Oracle7 ,8 and 9).
e Elapsed time (100th's of a second Oracle7, 8 and 1,000,000ths(Microseconds) in Oracle 9 onwards).
p Number of physical reads.
cr Number of buffers retrieved for CR reads.
cu Number of buffers retrieved in current mode.
mis Cursor missed in the cache.
r Number of rows processed.
dep Recursive call depth (0 = user SQL, >0 = recursive).
og Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
tim Timestamp (large number in 100ths of a second). Use this to
determine the time
ERROR #%d:err=%d tim=%luSQL Error shown after an execution or fetch error.
err Oracle error code (e.g. ORA-XXXXX) at the top of the stack.tim Timestamp.
STAT # id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']STAT Lines report explain plan statistics for the numbered .
Cursor which the statistics apply to.
id Line of the explain plan which the row count applies to (starts at
line 1). This is effectively the row source row
-
8/8/2019 All About Tracing Oracle SQL Sessions
6/12
count for all row sources in the execution tree.
cnt Number of rows for this row source.
As of 7.3.3 the items in '[...]' are also reported:
pid Parent id of this row source.
pos Position in explain plan.
obj Object id of row source (if this is a base object).op='...' The row source access operation.
These let you know the 'run time' explain plan.
XCTEND rlbk=%d rd_only=%d
XCTEND A transaction end marker.
rlbk 1 if a rollback was performed, 0 if no rollback (commit).
rd_only 1 if transaction was read only, 0 if changes occurred.
==========================================================The items below are only output if WAITS or BINDS are being traced.These can be enabled with the DBMS_SUPPORT package.==========================================================BINDS #%d: bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24offset=0 bfp=02fedb44 bln=22 avl=00 flg=05 value=10
BIND
Variables bound
to a cursor.
bindN The bind position being bound.
dty Data type (see ).
mxl Maximum length of the bind variable (private max len
in paren).
mal Array length.
scl Scale.
pre Precision.
oacflg Special flag indicating bind options
oacflg2 Continuation of oacflg
size Amount of memory to be allocated for this chunk
offset Offset into this chunk for this bind buffer
bfp Bind address.
bln Bind buffer length.
avl Actual value length (array length too).
flg Special flag indicating bind status
value The actual value of the bind variable.
Numbers show the numeric value, strings show the
string etc...
WAIT #: nam="" ela=0 p1=0 p2=0 p3=0
-
8/8/2019 All About Tracing Oracle SQL Sessions
7/12
WAIT An event that we waited for.
nam What was being waited for .
The wait events here are the same as are seen in
. For any Oracle release a full list
of
wait events and the values in P1, P2 and P3 below can beseen in
ela Elapsed time for the operation
p1 p1 for the given wait event
p2 p2 for the given wait event
p3 p3 for the given wait event
Example (Full Table Scan):
WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25
WAITing under CURSOR no 1
for "db file scattered read"
We waited 0.05 seconds
For a read of: File 4, start block 1435, for 25 Oracle
blocks
Example (Index Scan):
WAIT #1: nam="db file sequential read" ela= 4 p1=4 p2=1224 p3=1
WAITing under CURSOR no 1
for "db file sequential read"
We waited 0.04 seconds for a single block read (p3=1)
from file 4, block 1224.
-
8/8/2019 All About Tracing Oracle SQL Sessions
8/12
HOW TO find SQL trace file directories
Platform: Oracle App:DB Ver: 9.2 App Ver:Revision Date: 17-Sep-2005 Keyword
s:
HOWTO, TRACE FILES, DIRECTORIES, DIRECTORY
GoalTo find directories on the database server where SQL trace files are locatedFactsSolution
Run the SQL script:
SELECT name, value
FROM v$parameter2
WHERE name IN ('user_dump_dest'
,'background_dump_dest'
,'core_dump_dest')
-
8/8/2019 All About Tracing Oracle SQL Sessions
9/12
HOW TO find a user's session info for tracing
Platform: Oracle App:
DB Ver: 9.2 App Ver:
RevisionDate:
12-Sep-2005 Keywords: HOWTO, TRACING, TRACE, SESSION
GoalTo find a user's session info (ready for tracing)FactsSolution
The following SQL script will find the SID and SERIAL# required to activate asession specific SQL trace, together with supporting information about thatsession.
SELECT
s.sid db_sid
,s.serial# db_serial
,p.spid os_pid
,to_char(s.logon_time, 'YYYY/MM/DD HH24:MI:SS') db_logon_time
,nvl(s.username, 'SYS') db_user
,s.osuser os_user
,s.machine os_machine
,nvl(decode(instr(s.terminal, chr(0))
,0
,s.terminal
,substr(s.terminal, 1, instr(s.terminal, chr(0))-1)),'none')
os_terminal
,s.program os_program
from
v$session s
,v$process p
where 1=1
and s.paddr = p.addr
and s.username like upper('&1')
/
-
8/8/2019 All About Tracing Oracle SQL Sessions
10/12
HOW TO find a concurrent program's trace file
Platform: Oracle App:DB Ver: 9.2 App Ver:Revision Date: 28-Jun-2006 Keyword
s:
HOWTO, TRACE, CONCURRENT PROGRAM
GoalTo find the SQL trace file for a concurrent programFactsSolutionRun the following script:
prompt
ACCEPT request prompt 'Please enter the concurrent request id for
the appropriate concurrent program:'
prompt
COLUMN traceid format a8
COLUMN tracename format a80
COLUMN user_concurrent_program_name format a40
COLUMN execname format a15
COLUMN enable_trace format a12
SET lines 80
SET pages 22
SET head OFF
SELECT
req.request_id
,req.logfile_node_name node
,req.oracle_Process_id
,req.enable_trace
,dest.VALUE||'/'||LOWER(dbnm.VALUE)||'_ora_'||
oracle_process_id||'.trc' trace_filename
,prog.user_concurrent_program_name
,execname.execution_file_name,execname.subroutine_name
,phase_code
,status_code
,ses.SID
,ses.serial#
,ses.module
-
8/8/2019 All About Tracing Oracle SQL Sessions
11/12
,ses.machine
FROM
fnd_concurrent_requests req
,v$session ses
,v$process proc,v$parameter dest
,v$parameter dbnm
,fnd_concurrent_programs_vl prog
,fnd_executables execname
WHERE 1=1
AND req.request_id = &request
AND req.oracle_process_id=proc.spid(+)
AND proc.addr = ses.paddr(+)
AND dest.NAME='user_dump_dest'AND dbnm.NAME='db_name'
AND req.concurrent_program_id = prog.concurrent_program_id
AND req.program_application_id = prog.application_id
AND prog.application_id = execname.application_id
AND prog.executable_id=execname.executable_id
-
8/8/2019 All About Tracing Oracle SQL Sessions
12/12
HOW TO trace SQL*Plus client
Platform: Oracle App:DB Ver: 9.2 App Ver:
RevisionDate: 19-Oct-2005 Keywords: HOWTO, TRACE, SQL*PLUS
GoalSwitch tracing on for the SQL*Plus client applicationFactsSolution
To set up the trace on client:Include the following parameters in SQLNET.ORA file located in$ORACLE_HOME/network/admin:
trace_level_client = 16
trace_file_client = cli.trc
trace_directory_client = c:\tmp
trace_unique_client = on
trace_timestamp_client = on
trace_filelen_client = 100
trace_fileno_client = 2
log_file_client = cli
log_directory_client = c:\tmp
tnsping.trace_directory = c:\tmp
tnsping.trace_level = admin