• Skip to primary navigation
  • Skip to main content
  • Skip to primary sidebar
Techgoeasy

Techgoeasy

Learn Oracle, PHP, HTML,CSS,Perl,UNIX shell scripts

  • Home
  • Oracle
    • Oracle database
    • Oracle Ebusiness Suite
    • Oracle weblogic
    • Oracle Performance Tuning
    • Oracle Hyperion
    • Oracle Cloud Tutorials
  • SQL
  • interview questions
  • Linux
  • PHP and HTML
  • Downloads
  • General
Home » Oracle » Oracle Database » SQL trace, 10046 event in Oracle : trcsess, tkprof utility

SQL trace, 10046 event in Oracle : trcsess, tkprof utility

July 5, 2019 by techgoeasy 1 Comment

Tracing is a important part for Oracle database tuning. This will help capture all the problem statement , wait event which are responsible for slow running of the session.
Oracle database has provided has many quickest ways to trace the local session, other user session   and format the trace to make readable
SQL trace, 10046 event

Let us take some look at how to turn on SQL trace, 10046 event in  Oracle database and trcsess, tkprof utility

Table of Contents

  • SQL Trace ,100046 event
  • How to identify the Trace files
  • how to check if trace is enabled in oracle
  • Oracle tkprof utility
  • Oracle trcsess utility

SQL Trace ,100046 event

If you want to trace in local session,here are the steps to turn on SQL trace 

Normal trace

alter session set sql_trace = true;  -- To put trace on

alter session set sql_trace = false;  -- To put trace off

Full level with wait event And bind trace

alter session set events = ‘10046 trace name context forever, level 12’;

To put tracing off

alter session set events = ‘10046 trace name context off’;

Same as Normal trace

exec DBMS_SESSION.set_sql_trace(sql_trace => TRUE);

exec DBMS_SESSION.set_sql_trace(sql_trace => FALSE);

If you want to trace in other running session,here are the steps

Normal trace

execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true);  -- To put tracing on

execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true);   -- To put tracing off

Full level with wait event And bind trace

execute dbms_system.set_ev(‘sid’,’serial’,10046,12,’’);

To put trace off

execute dbms_system.set_ev(‘sid’,’serial’,10046,0,’’);

You must have seen using 12,0 in various statement above.They are tracing levels.Oracle Tracing has  tracing levels .Here are the valid values

0No trace. Like switching sql_trace off.
2The equivalent of regular sql_trace
It Provides execution path,row counts,smallest flat file
Advantages
Provides execution path
Provides row counts
Produces smallest flat file
Disadvantages
Cannot tell what values were supplied at run time to SQL
If statistics for query are low but run time is long cannot tell what events caused the long wait
4The same as 2, but with the addition of bind variable values
Advantages
Provides execution path
Provides row counts
Can tell what values the statement was run for
Disadvantages
Again if run time is long and statistics are low it will be hard to tell why in this type of trace.
Produces a bigger flat file that the regular trace because bind variable information has to be stored.
8The same as 2, but with the addition of wait events
Regular Trace plus database operation timings that the SQL waited to have done in order to complete. For example: disk access timings.
Advantages
Provides execution path
Provides row counts
Can tell timings for all events associated with SQL.
Disadvantages
Trace file may easily max out due to all the information Oracle must write to the trace file and then only partial information is available in trace file.
Bind variable information is not available
12The same as 2, but with both bind variable values and wait events
Regular trace with the both the wait and bind information. Contains the most complete information and will produce the largest trace file.
Provides execution path
Provides row counts
Can tell timings for all events associated with SQL.
Can tell what values the SQL was run with
Advantages
Provides execution path
Provides row counts
Can tell timings for all events associated with SQL.
Can tell what values the SQL was run with
Disadvantages
Trace file may easily max out due to all the information Oracle must write to the trace file and then only partial information is available in trace file.

There are other ways to do the tracing also. Here are some of these
(1) ORADEBUG
This requires login as sysdba

oradebug setospid   1111   -- Debug session with the specified Oracle  process id

oradebug setorapid  1111  --- Debug session with the specified OS process

oradebug event 10046 trace name context forever, level 4;

oradebug event 10046 trace name context off;   --- This disable the trace

oradebug close_trace  --- This closes  the trace file

Oradebug TRACEFILE_NAME;

(2) With Oracle 10g the SQL tracing options have been  extended using the DBMS_MONITOR package

EXECUTE dbms_monitor.session_trace_enable

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 2';

EXECUTE dbms_monitor.session_trace_enable (binds=>true);

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 4';

EXECUTE dbms_monitor.session_trace_enable (waits=>true);

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

EXECUTE dbms_monitor.session_trace_enable('sid','serial#')

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,2,’’);

EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',binds=>true);

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,4,’’);

EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',waits=>true);

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,8,’’);

There are many other functionality available in dbms_monitor. We can enable trace based on client identifier and multiple ways

How to identify the Trace files

We can identify the trace files using the spid of the session. Also the trace file will  contain sid,serial#  pair at the start of the trace file.
Below query can be used to find the local session trace file

select c.value || '/' || d.instance_name ||'_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'
/

There is another easy way to identify the trace file  which is called trace identifier

alter session set tracefile_identifer=’ORAC’;  This is identifier

Example trace file

Trace file /app/oracle/TEST/diag/rdbms/test/TEST/trace/TEST_ora_13025_IDEN.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /app/oracle/TEST/11.2.0/db
System name:    SunOS12
Node name: sun12Release:   5.10Version:   Generic_144488-11
Machine:   sun4u
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 202
Unix process pid: 13025, image: [email protected] SunOS12
*** 2013-10-21 12:28:56.461
*** SESSION ID:(3875.17341) 2013-10-21 12:28:56.461*** CLIENT ID:() 2013-10-21 12:28:56.461
*** SERVICE NAME:(TEST) 2013-10-21 12:28:56.461
*** MODULE NAME:([email protected](TNS V1-V3)) 2013-10-21 12:28:56.461
*** ACTION NAME:() 2013-10-21 12:28:56.461
CLOSE #4:c=0,e=11,dep=1,type=1,tim=8866891135825
=====================
PARSING IN CURSOR #5 len=356 dep=1 uid=173 oct=3 lid=173 tim=8866891136821 hv=2468783182 ad='4c70e4398' sqlid='0wmwsjy9kd92f'SELECT PROFILE_OPTION_ID, APPLICATION_ID, SITE_ENABLED_FLAG , APP_ENABLED_FLAG , RESP_ENABLED_FLAG , USER_ENABLED_FLAG, ORG_ENABLED_FLAG , SERVER_ENABLED_FLAG, SERVERRESP_ENABLED_FLAG, HIERARCHY_TYPE, USER_CHANGEABLE_FLAG FROM FND_PROFILE_OPTIONS WHERE PROFILE_OPTION_NAME = :B1 AND START_DATE_ACTIVE <= SYSDATE AND NVL(END_DATE_ACTIVE, SYSDATE) >= SYSDATEEND OF STMT
BINDS #5:
Bind#0
oacdty=01 mxl=128(80) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=01 csi=871 siz=128 off=0
kxsbbbfp=ffffffff7d677b48  bln=128  avl=21  flg=0
value="PER_BUSINESS_GROUP_ID"
EXEC #5:c=0,e=1474,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1374985481,tim=8866891138224
FETCH #5:c=0,e=61,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=1374985481,tim=8866891138429
CLOSE #5:c=0,e=5,dep=1,type=3,tim=8866891138503
=====================
PARSING IN CURSOR #4
 len=230 dep=1 uid=173 oct=3 lid=173 tim=8866891138634 hv=3575592451 ad='3aeea3da0' sqlid='55dc767ajydh3'
SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = 10003 AND LEVEL_VALUE = :B2 AND LEVEL_VALUE_APPLICATION_ID = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL
END OF STMT
BINDS #4:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0
kxsbbbfp=ffffffff7d677b68  bln=22  avl=03  flg=05
value=1204
Bind#1
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24
kxsbbbfp=ffffffff7d677b80  bln=22  avl=02  flg=01
value=800
Bind#2
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48
kxsbbbfp=ffffffff7d677b98  bln=22  avl=04  flg=01
value=50334
Bind#3
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=72
kxsbbbfp=ffffffff7d677bb0  bln=22  avl=01  flg=01
value=0
EXEC #4:c=0,e=377,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891138978
FETCH #4:c=0,e=26,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891139050
CLOSE #4:c=0,e=2,dep=1,type=3,tim=8866891139116
=====================
PARSING IN CURSOR #5 
len=191 dep=1 uid=173 oct=3 lid=173 tim=8866891139308 hv=303338305 ad='3bedf0e48' sqlid='7qs7fx89194u1'
SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = :B2 AND LEVEL_VALUE = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL
END OF STMT
BINDS #5:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0
kxsbbbfp=ffffffff7d673b78  bln=22  avl=03  flg=05
value=1204
Bind#1
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24
kxsbbbfp=ffffffff7d673b90  bln=22  avl=02  flg=01
value=800
Bind#2
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48
kxsbbbfp=ffffffff7d673ba8  bln=22  avl=04  flg=01
value=10001

how to check if trace is enabled in oracle

If you have enabled tracing using DBMS_MONITOR package, we can check if trace is enabled using below query

set lines 180
col module for a45
col sql_trace_waits for a20
col sql_trace_binds for a20
col sql_trace for a20
select username,module,sid,sql_trace,sql_trace_waits,sql_trace_binds from v$session where sql_trace='ENABLED'
/

If it is enable through other methods, then the only way to check is look at the trace location and find out the trace files which are recent and then find the sid and serial# in it and then you can query v$session to find the session and you can disable the trace if you want

Oracle tkprof utility

The trace files obtained from above method is in raw  form which can be converted into more readable format using tkprof utility  (Transient Kernel PROFile  utility)

tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
print=integer    List only the first 'integer' SQL statements.
aggregate=yes|no
insert=filename  List SQL statements and data inside INSERT statements.
sys=no           TKPROF does not list SQL statements run as user SYS.
record=filename  Record non-recursive statements found in the trace file.
waits=yes|no     Record summary for any wait events found in the trace file.
sort=option      Set of zero or more of the following sort options:
prscnt  number of times parse was called
prscpu  CPU time parsing
prsela  elapsed time parsing    
prsdsk  number of disk reads during parse 
prsqry  number of buffers for consistent read during 
parseprscu   number of buffers for current read during 
parseprsmis  number of misses in library cache during 
parseexecnt  number of execute was called 
execpu  CPU time spent executing exeela  elapsed time executing 
exedsk  number of disk reads during execute 
exeqry  number of buffers for consistent read during execute

execu   number of buffers for current read during execute

exerow  number of rows processed during execute

exemis  number of library cache misses during execute

fchcnt  number of times fetch was called

fchcpu  cpu time spent fetching

fchela  elapsed time fetching

fchdsk  number of disk reads during fetch

fchqry  number of buffers for consistent read during fetch

fchcu   number of buffers for current read during fetch

fchrow  number of rows fetched

userid  userid of user that parsed the cursor

Some examples

tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela
tkprof file.trc file.txt  sys=no explain=userid/password  sort=prsela,exeela,fchela
tkprof file.trc file.txt sys=no
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela
This print 10 sql only
tkprof .trc elaps.prf sys=no explain=apps/ sort=(prsela,exeela,fchela) print=10
This print all the sql
tkprof .trc elaps.prf sys=no explain=apps/apps sort=prsela,exeela,fchela

Example content of tkprof file

TKPROF: Release 11.2.0.4.0 - Production on Tue Jan 17 14:12:41 2013
Copyright (c) 1982, 2007, Oracle.  All rights reserved.
Trace file: TEST_ora_15941.trc
Sort options: execpu  fchcpu
********************************************************************************
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
********************************************************************************
SQL ID: 6w82ggrtysx
Plan Hash: 2325776775
SELECT FUNCTION_NAME    FROM FND_USER_DESKTOP_OBJECTS  WHERE USER_ID = :b1  AND APPLICATION_ID = :b2  AND  RESPONSIBILITY_ID = :b3  AND TYPE = 'FUNCTION'  AND ROWNUM <= 10 ORDER BY SEQUENCE
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          4          0           1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
1          1          1  SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=6 size=41 card=1)
1          1          1   COUNT STOPKEY (cr=4 pr=0 pw=0 time=0 us)
1          1          1    TABLE ACCESS BY INDEX ROWID FND_USER_DESKTOP_OBJECTS (cr=4 pr=0 pw=0 time=0 us cost=5 size=41 card=1)
1          1          1     INDEX RANGE SCAN FND_USER_DESKTOP_OBJECTS_N1 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=3)(object id 33596)
Rows     Execution Plan
-------  ---------------------------------------------------
0  SELECT STATEMENT   MODE: ALL_ROWS
1   SORT (ORDER BY)
1    COUNT (STOPKEY)
1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
'FND_USER_DESKTOP_OBJECTS' (TABLE)
1      INDEX   MODE: ANALYZED (RANGE SCAN) OF
'FND_USER_DESKTOP_OBJECTS_N1' (INDEX)
Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
SQL*Net message to client                       5        0.00          0.00
SQL*Net message from client                     5        0.00          0.00********************************************************************************
SQL ID: 276ut2ywqux
Plan Hash: 3856112528
select object_name, icon_name
from
fnd_desktop_objects
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.00          0          6          0          47
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          6          0          47
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
47         47         47  TABLE ACCESS FULL FND_DESKTOP_OBJECTS (cr=6 pr=0 pw=0 time=0 us cost=2 size=1175 card=47)
Rows     Execution Plan
-------  ---------------------------------------------------
0  SELECT STATEMENT   MODE: ALL_ROWS
47   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'FND_DESKTOP_OBJECTS'
(TABLE)

Oracle trcsess utility

When using shared server sessions, many processes are involved. The trace pertaining to the user session is scattered across different trace files belonging to different processes. This makes it difficult to get a complete picture of the life cycle of a session.
The trcsess utility consolidates trace output from selected trace files based on several criteria

trcsess  [output=output_file_name] [session=session_id] [clientid=client_id] [service=service_name] [action=action_name] [module=module_name] [trace_files]

trcsess output=main.trc service=TEST  *trc 

After the consolidate trace file had been generated you can execute tkprof on it.

More Information

In 11g and higher, sql_trace is also an event and can be set with event syntax:

SQL> oradebug doc event name sql_trace

sql_trace: event for sql trace

Usage
-------
sql_trace
wait < false | true >,
bind < false | true >,
plan_stat < never | first_execution | all_executions | adaptive >,
level <ub4>

So you could use it as follows to enable SQL_TRACE requesting bind information:

alter session set events 'sql_trace bind=true';

or bind and wait information (notice comma separated):

alter session set events 'sql_trace bind=true, wait=true';

Further trace can be limited to a set of SQL_IDs if you include a filter for it. E.g.

alter session set events 'sql_trace [sql: sql_id=g3yc1js3g2689 | sql_id=7ujay4u33g337]bind=true, wait=true';

10046 EVENT levels: (the new sql_trace values are included in [..])
These are bit values so can be put together to get different mixes
1 – Enable standard SQL_TRACE functionality (Default)
4 – As Level 1 PLUS trace bind values [ bind=true ]
8 – As Level 1 PLUS trace waits [ wait=true ]
This is especially useful for spotting latch wait etc.
but can also be used to spot full table scans and index scans.

As of 11g these additional bit levels are available:
16 – Generate STAT line dumps for each execution [ plan_stat=all_executions ]
32 – Never dump execution statistics [ plan_stat=never ]

As of 11.2.0.2 this additional bit level is available:
64 – Adaptive dump of STAT lines. [ plan_stat=adaptive ]
This dumps the STAT information if a SQL took more than about 1 minute thereby
giving information for the more expensive SQLs and for different executions of such
SQLs.

eg: A common event level is 12 which includes standard SQL_TRACE output, binds, waits and
default STAT line tracing.

Notes:
STAT dumping has been amended in 11g so that they are not aggregated across all executions but are dumped after execution. This has been done to address cases where the cursor is not closed and the STAT information is therefore not dumped.
Now we guarantee to capture the STAT information following the execution. See the above bit levels to have finer control over STAT lines.

Also Reads
v$active_session_history
explain plan in Oracle
sql tuning Advisor

Filed Under: Oracle, Oracle Database Tagged With: 10046 event, 10046 event in Oracle database and trcsess, SQL trace, tkprof utlity, tkprof.trace

Reader Interactions

Comments

  1. Anurag says

    October 26, 2021 at 3:32 am

    Thanks so much for the all the detailed and well organized information. Much appreciated!

    Reply

Leave a Reply Cancel reply

Your email address will not be published. Required fields are marked *

Primary Sidebar



Subscribe to our mailing list

Enter your email address to subscribe to this blog and receive notifications of new posts by email

Recent Posts

  • Password Version in oracle
  • How to login as user without changing the password in Oracle database(alter user identified by values)
  • How to check encrypted tablespace in the Database
  • How To Export -Import TDE Master Encryption Key
  • How to Configure Auto Login TDE Wallet

Copyright © 2023 : TechGoEasy

  • Hire me
  • Privacy Policy
  • Contact Us
  • New? Start Here
  • About Us