Oracle Application/session tracing methods - 3

 This is a continuation of the previous posts regarding how to trace an individual session as discussed in the below link

Oracle Application/session tracing methods - 1

and the methods of how to trace the sessions at application or database level as discussed in the below link

Oracle Application/session tracing methods - 2

You might see when we start tracing at application level, we get a bunch of trace files as there are multiple session involved. For eg., when we trace using a module, multiple sessions can run queries involving same module. In such cases, we can't go dig each and every trace file to investigate the issue. It would be much easier if we have a single consolidated trace file so that we can have a better understand of the issue we are investigating. Also, the trace file needs to be in human readable format rather some bunch of random random numbers here and there which only the computer can understand. 

In this post we are going to look at how to consolidate multiple trace files as well how to make these trace files human readable using the below tools

• trcsess
• tkprof

trcsess

We can use the trcsess to consolidate trace files based on several criteria such as 

• Session id
• Client id
• Service name
• Action name
• Module name

Let's see how to use this tool with an example. In my previous post, when I mentioned about tracing session with service name, I used Swingbench to generate load using 4 session. The session traces are as below

..
..
-rw-r-----. 1 oracle oinstall  4954796 Dec 15 00:25 orcl_ora_19415.trm
-rw-r-----. 1 oracle oinstall 44587093 Dec 15 00:25 orcl_ora_19415.trc
-rw-r-----. 1 oracle oinstall  4233304 Dec 15 00:25 orcl_ora_19413.trm
-rw-r-----. 1 oracle oinstall 37791460 Dec 15 00:25 orcl_ora_19413.trc
-rw-r-----. 1 oracle oinstall  4911273 Dec 15 00:25 orcl_ora_19411.trm
-rw-r-----. 1 oracle oinstall 44277819 Dec 15 00:25 orcl_ora_19411.trc
-rw-r-----. 1 oracle oinstall  3892558 Dec 15 00:25 orcl_ora_19409.trm
-rw-r-----. 1 oracle oinstall 34574211 Dec 15 00:25 orcl_ora_19409.trc
..
..

These 4 traces can be consolidated into a single trace file as below

Syntax: trcsess [output=] [session=] [clientid=] [service=] [action=] [module=]

[oracle@linux75-2 trace]$
[oracle@linux75-2 trace]$ trcsess output=service_orcl_trace.trc service=ORCL orcl_ora_19415.trc orcl_ora_19413.trc orcl_ora_19411.trc orcl_ora_19409.trc
[oracle@linux75-2 trace]$
[oracle@linux75-2 trace]$ ls -lrt service_orcl_trace.trc
-rw-r--r--. 1 oracle oinstall 161234967 Dec 19 23:56 service_orcl_trace.trc
[oracle@linux75-2 trace]$ head -20 service_orcl_trace.trc
*** [ Unix process pid: 19415 ]
*** 2021-12-15T00:25:01.309981+05:30
*** [ Unix process pid: 19413 ]
*** 2021-12-15T00:25:01.309867+05:30
*** [ Unix process pid: 19409 ]
*** 2021-12-15T00:25:01.309928+05:30
*** [ Unix process pid: 19415 ]
*** 2021-12-15T00:25:01.309986+05:30
*** [ Unix process pid: 19413 ]
*** 2021-12-15T00:25:01.309871+05:30
*** [ Unix process pid: 19409 ]
*** 2021-12-15T00:25:01.309933+05:30
*** [ Unix process pid: 19415 ]
*** 2021-12-15T00:25:01.309990+05:30
*** CLIENT DRIVER:() 2021-12-15T00:25:01.309999+05:30

WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=11623002622
WAIT #0: nam='SQL*Net message from client' ela= 111757 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=11623121966
WAIT #0: nam='latch: shared pool' ela= 230 address=1613615352 number=551 why=1787423120 obj#=-1 tim=11623122364
WAIT #0: nam='library cache load lock' ela= 13162 object address=1757868440 lock address=1759806192 100*mask+namespace=5177347 obj#=-1 tim=11623135636
[oracle@linux75-2 trace]$ 

You can notice that I'm providing the trace files for the trcsess to look into for trace details, otherwise trcsess will look into all the trace files inside the trace directory. 

Also, once the trace files are consolidated, the trace file shows the pid of all the sessions traced in the beginning. 

tkprof

The raw trace file as I mentioned in the beginning of this post is in Oracle proprietary format like below. 

..
..
*** 2021-12-15T00:25:01.309990+05:30
*** CLIENT DRIVER:() 2021-12-15T00:25:01.309999+05:30

WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=11623002622
WAIT #0: nam='SQL*Net message from client' ela= 111757 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=11623121966
WAIT #0: nam='latch: shared pool' ela= 230 address=1613615352 number=551 why=1787423120 obj#=-1 tim=11623122364
WAIT #0: nam='library cache load lock' ela= 13162 object address=1757868440 lock address=1759806192 100*mask+namespace=5177347 obj#=-1 tim=11623135636
WAIT #139804731097848: nam='cursor: pin S wait on X' ela= 2567 idn=3873422482 value=1735166787584 where=21474836480 obj#=-1 tim=11623138951
=====================
PARSING IN CURSOR #139804731097848 len=82 dep=1 uid=0 oct=3 lid=0 tim=11623139023 hv=3873422482 ad='71383950' sqlid='0k8522rmdzg4k'
select privilege# from sysauth$ where (grantee#=:1 or grantee#=1) and privilege#>0
END OF STMT
PARSE #139804731097848:c=379,e=3165,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2057665657,tim=11623139020
EXEC #139804731097848:c=161,e=161,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2057665657,tim=11623139260
FETCH #139804731097848:c=74,e=74,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2057665657,tim=11623139366
WAIT #139804731068608: nam='cursor: pin S wait on X' ela= 3282 idn=3008674554 value=1735166787584 where=21474836480 obj#=-1 tim=11623142719
=====================
PARSING IN CURSOR #139804731068608 len=226 dep=1 uid=0 oct=3 lid=0 tim=11623142772 hv=3008674554 ad='71378ba8' sqlid='5dqz0hqtp9fru'
select /*+ connect_by_filtering index(sysauth$ i_sysauth1) */ privilege#, bitand(nvl(option$, 0), 72), grantee#, level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0
END OF STMT
PARSE #139804731068608:c=169,e=3381,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1227530427,tim=11623142771
WAIT #139804731068608: nam='PGA memory operation' ela= 8 p1=131072 p2=2 p3=0 obj#=-1 tim=11623142861
EXEC #139804731068608:c=118,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1227530427,tim=11623142960
WAIT #139804731068608: nam='PGA memory operation' ela= 7 p1=65536 p2=1 p3=0 obj#=-1 tim=11623143087
FETCH #139804731068608:c=209,e=209,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=4,plh=1227530427,tim=11623143182
FETCH #139804731068608:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1227530427,tim=11623143213
STAT #139804731068608 id=1 cnt=1 pid=0 pos=1 obj=0 op='CONNECT BY WITH FILTERING (cr=5 pr=0 pw=0 str=1 time=215 us)'
STAT #139804731068608 id=2 cnt=1 pid=1 pos=1 obj=144 op='TABLE ACCESS BY INDEX ROWID BATCHED SYSAUTH$ (cr=3 pr=0 pw=0 str=1 time=29 us cost=3 size=20 card=2)'
STAT #139804731068608 id=3 cnt=1 pid=2 pos=1 obj=147 op='INDEX RANGE SCAN I_SYSAUTH1 (cr=2 pr=0 pw=0 str=1 time=6 us cost=2 size=0 card=2)'
STAT #139804731068608 id=4 cnt=0 pid=1 pos=2 obj=0 op='HASH JOIN  (cr=2 pr=0 pw=0 str=1 time=125 us cost=7 size=115 card=5)'
..
..

This is partially understandable but wouldn't it be nice to see the trace file in a more readable and easily understandable format? 

For this we have tkprof (transient kernel profiler) provided by Oracle. tkprof accepts a trace file as input and produces a formatted output file and there a few options that we can make use of. Explain plan for the captured queries can also be made available as an option. Usage is as below

[oracle@linux75-2 trace]$ 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.
  pdbtrace=user/password   Connect to ORACLE to retrieve SQL trace records.
  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 parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  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

[oracle@linux75-2 trace]$ tkprof service_orcl_trace.trc service_orcl_trace.out explain='sys as sysdba' table=sys.tkprof_table sys=no sort=exeela,execpu waits=yes

TKPROF: Release 12.2.0.1.0 - Development on Mon Dec 20 00:25:40 2021

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


password =
[oracle@linux75-2 trace]$ 

I have provided service_orcl_trace.trc file as input to tkprof to convert the file to service_orcl_trace.out file with explain plan for the queries along with their wait time statistics. 

I don't want to see the recursive calls made by sys and hence mentioned sys=no and would like to sort the output of the trace file with queries execute elapsed time and cpu time spent executing. 

Sample output produced by tkprof will look like below

 
********************************************************************************

SQL ID: 982zxphp8ht6c Plan Hash: 1666523684

select product_id, product_name, product_description, category_id,
  weight_class, supplier_id, product_status, list_price, min_price,
  catalog_url
from
  product_information where product_id = :1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    95536      0.57       0.91          0          0          0           0
Execute  95536      1.00       1.58          0          0          0           0
Fetch    95536      0.80       1.32         28     286608          0       95536
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   286608      2.38       3.81         28     286608          0       95536

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 89
Number of plan statistics captured: 6

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID PRODUCT_INFORMATION (cr=3 pr=1 pw=0 time=543 us starts=1 cost=2 size=176 card=1)
         1          1          1   INDEX UNIQUE SCAN PRODUCT_INFORMATION_PK (cr=2 pr=0 pw=0 time=244 us starts=1 cost=1 size=0 card=1)(object id 24503)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   95536        0.00          0.16
  db file sequential read                        28        0.00          0.02
  SQL*Net message from client                 95536        0.01         24.82
  cursor: pin S                                  15        0.00          0.01
  latch: cache buffers chains                     1        0.00          0.00
********************************************************************************
 

The trace file now looks neat and easy to understand which can be interpreted and investigated for performance issues. 

A simple interpretation would be this specific select query has been run 95536 times with 28 blocks read for the disk or physical i/o and made 286608 logical i/o ti fetch 95536 records. This means the query is bringing 1 records per execution. Total elapsed time is 3.81 seconds with 2.38 seconds spent in cpu. The investigation can go for different queries to pin point the issues with the help of this tkprof trace file report. 

So we conclude our tracing methods with this and I hope it is easy to follow and understand. 

References: 

What is TRCSESS and How to use it ? (Doc ID 280543.1)

QREF: TKPROF Usage - Quick Reference (Doc ID 29012.1)

Using SQL Trace and TKPROF (oracle.com)

Pic courtesy: www.oracle.com

Happy tracing...!!!

Oracle Application/session tracing methods - 2

 In my previous post, we saw how to trace individual sessions. The challenge involved in real world performance issues is that mostly there won't be any single session that would run in the DB but the application would spawn multiple processes/sessions. So in this case if we want to trace a session, it will be tedious task to identify which session to trace. Many time there would be run away sessions and a few times even the developers wouldn't be knowing the entire work flow which will again add complexity to the existing issue. 

During these times, instead of tracing individual session we can go ahead and trace set of sessions using application tracing methods. In this post, we will look at the methods on how to do the application tracing

Application level tracing

Application tracing can be performed by using 

• DBMS_SQL_MONITOR
• DBMS_MONITOR

We will have a separate post on DBMS_SQL_MONITOR later and now will look into the usage of DBMS_MONITOR

DBMS_MONITOR

Information that we need to proceed with application tracing using dbms_monitor are either of the 3 below

• Client info
• Module
• Action

All of the 3 might or might not be obtained from v$session as v$session could also contain null for these fields. For eg:

SQL> set sqlformat ansiconsole
SQL> select sid, serial#, username, client_info, module, action from v$session where username not in ('SYS','SYSTEM')
SID   SERIAL#  USERNAME  CLIENT_INFO  MODULE                                          ACTION
---------------------------------------------------------------------------------------------
17    63073    SOE       Swingbench Load Generator  JDBC Thin Client
401   47594    SOE       Swingbench Load Generator  JDBC Thin Client
778   11025    SOE                                  SQL*Plus
780   55219    SYSRAC                               oraagent.bin@linux75-2.selvapc.com (TNS V1-V3)
1151  4268     SOE       Swingbench Load Generator  JDBC Thin Client
1157  61639    SYSRAC                               oraagent.bin@linux75-2.selvapc.com (TNS V1-V3)
1158  10873    TEST                                 SQL Developer
1166  11417    SOE       Swingbench Load Generator  JDBC Thin Client


8 rows selected.

SQL> 

You can see a few session has CLIENT_INFO and a few doesn't and none of sessions has info on ACTION field. 

We can use DBMS_APPLICATION_INFO package to extract the details needed or to set them as well by using READ_CLIENT_INFO, READ_MODULE, SET_ACTION, SET_CLIENT_INFO or SET_MODULE procedures which will be explained below

READ_CLIENT_INFO and READ_MODULE can be used to read the details from the specific SID using v$session view

SET_ACTION, SET_CLIENT_INFO or SET_MODULE can be used to set the names for the specific program or piece of code which makes tracing easy. 

The below code provides an example of how to insert the DBMS_APPLICATION_INFO package in application program code making way for us to trace as desired. 

CREATE
	OR replace PROCEDURE up_test1 AS

BEGIN
	dbms_application_info.set_module(module_name=> 'Change name', action_name=> 'insert id');

	INSERT INTO test1 (id,name)
	VALUES (102,'ORABLISS');

	dbms_application_info.set_action(action_name=> 'update id');

	UPDATE test1
	SET id = 101
	WHERE name = 'test';

	dbms_application_info.set_module(NULL, NULL);
END;
/

You can see I have inserted DBMS_APPLICATION_INFO.SET_MODULE in 2 places one with module_name and action_name and another with only action_name. This way we can trace the parts only we need in code with large number of lines. 

Once we introduced the module_name or action_name we can trace the sessions running this piece of code without even knowing the session id of the sessions executing them. 

Use DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE procedure to trace sessions as desired for investigation

For tracing sessions using module_name:

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_ENABLE(service_name=>'ORCL',module_name=>'Change name');

PL/SQL procedure successfully completed.

-- Run the procedure using other session which will trigger the tracing 
-- Once the procedure is completed we can disable trace as follows. 

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_disable(service_name=>'ORCL',module_name=>'Change name');

PL/SQL procedure successfully completed.

SQL> 

For tracing sessions performing specific action:

we can also specify the action_name which will trigger tracing only when the specific action name is started in the program

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_ENABLE(service_name=>'ORCL',module_name=>'Change name',action_name=> 'update id',waits=>true,binds=>true);

PL/SQL procedure successfully completed.

-- Run the procedure using other session which will trigger the tracing 
-- This time tracing will capture only the update statement in the procedure as the action is named as 'update id'
-- Once the procedure is completed we can disable trace as follows. 

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_disable(service_name=>'ORCL',module_name=>'Change name',action_name=> 'update id');

PL/SQL procedure successfully completed.

SQL> 

The above SERV_MOD_ACT_TRACE_ENABLE procedure follows strict hierarchy, meaning - service_name is mandatory followed by module_name and action_name. If no module_name is provided, we can't provide action_name and if no action_anme is provided all the action under the module will be traced. 

For tracing sessions using specific service_name:

If we don't specify any module_name, all the sessions connecting to the DB using the service_name will be traced. Different applications can connect to same database using different service names as desired by the database admin to segregate them. 

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_ENABLE(service_name=>'ORCL');

PL/SQL procedure successfully completed.

-- This time tracing will capture all the sessions that connect to DB using ORCL service
-- We can disable trace as follows. 

SQL> exec dbms_monitor.SERV_MOD_ACT_TRACE_DISABLE(service_name=>'ORCL');

PL/SQL procedure successfully completed.

SQL> 

For tracing sessions using Client_identifier:

v$session will have client_info filed populated for most of the application. If it is null like the example I gave in this post, we can use the DBMS_APPLICATION_INFO.SET_CLIENT_INFO procedure to set in the program/main procedure similar to below

CREATE
	OR replace PROCEDURE up_test2 AS

BEGIN
	dbms_application_info.set_client_info('client info test');
	dbms_session.set_identifier('client info test');

	INSERT INTO test1 (id,name)
	VALUES (102,'ORABLISS');

	UPDATE test1
	SET id = 101
	WHERE name = 'test';
	
	dbms_session.clear_identifier;
END;
/

As I have now included the DBMS_SESSION.SET_IDENTIFIER, we can trace the session without searching for the session id. 

Setting only CLIENT_INFO will be useful to find the session details to enable tracing and for automatic tracing of session with client id, we need the dbms_session.set_identifier

SQL> exec DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE('client info test');

PL/SQL procedure successfully completed.

-- Run the procedure up_test2 using other session which will trigger the tracing using client identifier
-- Once the procedure is completed we can disable trace as follows (optional)

SQL> exec DBMS_MONITOR.CLIENT_ID_TRACE_disable('client info test');

PL/SQL procedure successfully completed.

SQL>

Database level tracing

The above methods explained regarding the options of tracing parts of database and its sessions. 

If a need arise to trace the entire database (I don't think any one would do this on a production database), we can do so by DBMS_MONITOR.DATABASE_TRACE_ENABLE procedure

SQL> exec DBMS_MONITOR.DATABASE_TRACE_ENABLE;

PL/SQL procedure successfully completed.

-- All the sessions in the database will be traced
-- waits, binds, instance_name and plan_stat can be provided as arguments

-- To disable tracing

SQL> exec DBMS_MONITOR.DATABASE_TRACE_DISABLE;

PL/SQL procedure successfully completed.

SQL>

With this, we have looked at all the ways we can trace the application/DB sessions. 

All the trace files generated will be in Oracle proprietary format. To convert the trace files generated and make use of the trace files, check this link on tkprof

References: 

DBMS_MONITOR (oracle.com)

General SQL_TRACE / 10046 trace Gathering Examples (Doc ID 1274511.1)

Happy Tracing

Oracle Application/session tracing methods - 1

 Tracing forms an important method when it comes to database and/or SQL performance tuning. In this blog post let's see the various methods we can trace a session or an application or an entire database and how to read the trace files generated 

Types of tracing: 

• Session level
• Application level
• Database level

Prerequisites

• Check timed_statistics value is TRUE;
• Check statistics_level is typical or all
• Set max_dump_file_size to unlimited so that the trace is not abruptly ended due to file size reached

Example tracing own session: 

When we need to trace the same session that we are connected to trouble shoot a query, we can perform the below

SQL_TRACE

[oracle@linux75-2 ~]$ sql soe/soe

SQLcl: Release 12.2.0.1.0 RC on Thu Dec 02 23:53:32 2021

Copyright (c) 1982, 2021, Oracle.  All rights reserved.

Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production


SQL> show parameter timed_statistics
NAME             TYPE    VALUE
---------------- ------- -----
timed_statistics boolean TRUE

SQL> show parameter statistics_level
NAME             TYPE   VALUE
---------------- ------ -------
statistics_level string TYPICAL

SQL> show parameter max_dump_file_size
NAME               TYPE   VALUE
------------------ ------ ---------
max_dump_file_size string unlimited

SQL> alter session set tracefile_identifier='MyTrace';

Session altered.

SQL> alter session set sql_trace=true;

Session altered.

SQL> -- Run the query that needs to be traced now
SQL> select count(*) from soe.addresses where country='India';

  COUNT(*)
----------
     19536

SQL> alter session set sql_trace=false;

Session altered.

SQL>

10046 tracing

We can also enable 10046 tracing to perform the same as below

SQL> -- set the identifier to find the trace file easily in the trace directory
SQL> alter session set tracefile_identifier='My10046';

Session altered.

SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

SQL> -- Run the query to be traced now
SQL> select count(*) from soe.addresses where country='India';

  COUNT(*)
----------
     19536

SQL> alter session set events '10046 trace name context off';

Session altered.

SQL> show parameter diag
NAME            TYPE   VALUE
--------------- ------ ---------
diagnostic_dest string /u01/orcl
SQL> exit

For 10046 tracing, the following values are valid for trace level

• 0 - Off
• 2 - Similar to regular sql_trace
• 4 - Same as 2, but with addition of bind variable values
• 8 - Same as 2, but with addition of wait events
• 12 - same as 2, but with both bind variable values and wait events

DBMS_SESSION package

Own session can also be traced using dbms_session package

SQL> alter session set tracefile_identifier='MySess';

Session altered.

SQL> exec DBMS_SESSION.SESSION_TRACE_ENABLE(waits=> true, binds=> true);

PL/SQL procedure successfully completed.

SQL> select count(*) from soe.addresses where country='India';

  COUNT(*)
----------
     19536

SQL> exec DBMS_SESSION.SESSION_TRACE_DISABLE();

PL/SQL procedure successfully completed.

SQL> exit

All the trace files will be available by default in the trace directory under diagnostic_dest. 

[oracle@linux75-2 ~]$ cd /u01/orcl/diag/rdbms/orcl/orcl/trace/
[oracle@linux75-2 trace]$ ls -lrt *My*
-rw-r-----. 1 oracle oinstall  1310 Dec  2 23:55 orcl_ora_8930_MyTrace.trm
-rw-r-----. 1 oracle oinstall  2560 Dec  2 23:55 orcl_ora_8930_MyTrace.trc
-rw-r-----. 1 oracle oinstall  2984 Dec  2 23:55 orcl_ora_8930_My10046.trm
-rw-r-----. 1 oracle oinstall 26449 Dec  2 23:55 orcl_ora_8930_My10046.trc
-rw-r-----. 1 oracle oinstall  3404 Dec  3 00:38 orcl_ora_12142_MySess.trm
-rw-r-----. 1 oracle oinstall 33729 Dec  3 00:38 orcl_ora_12142_MySess.trc
[oracle@linux75-2 trace]$ 

By default, the trace files will be generated by it's server process id. In the above, 8930 and 12142 are the process id of the sessions I logged into the database. Since there will be many processes running and by default oracle trace will be enabled for many background processes, we will be in a position that we are lost when searching for the trace file generated. To find the trace files easily, we are setting the tracefile_identifier as our first step of tracing. 

Example tracing another session:

In most circumstances as a DBA, we will not be tracing our own session but will have to another session whether a user is already logged in or is about to login. Let's take a look on how to we do this 

Start trace as soon as logon

We can create an after logon trigger to enable tracing for the session whenever a user logon to the database as below

CREATE OR REPLACE TRIGGER sys.set_trace AFTER LOGON ON DATABASE
WHEN ( user LIKE '&USERNAME' ) DECLARE
lcommand VARCHAR(200);
BEGIN
EXECUTE IMMEDIATE 'alter session set statistics_level=ALL';
EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';
DBMS_MONITOR.SESSION_TRACE_ENABLE (WAITS=> TRUE , BINDS=> TRUE);
END SET_TRACE ;
/

Note: The user on which the tracing should be enabled should explicitly have execute privilege on alter session and DBMS_MONITOR package. Otherwise the logon will fail due to insufficient privilege issue.

Start tracing when a session is identified for tracing

Many a times, when an issue is identified we will be in a situation where already a session is established in the database. So all we need to do is to get the details of SID and Serial# of the session to begin tracing of that session. Mostly these sessions are running with high cpu consumption or high waits or consuming high DB time. 

So once we figured out the SID and Serial#, the session trace can be done as below

SQL> -- Finding session id and serial # to enable trace
SQL> select username, sid, serial# from v$session where username='SOE';

USERNAME                              SID    SERIAL#
------------------------------ ---------- ----------
SOE                                   783      48974

SQL> -- Enable trace for the session
SQL> EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>783, SERIAL_NUM=>48974, WAITS=>TRUE, BINDS=>FALSE);

PL/SQL procedure successfully completed.

SQL> -- Now all the activities on session 783,48974 will be traced
SQL> -- We can disable trace once we have confirmation from user he/she completed their work to investigate
SQL>
SQL> EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>783, SERIAL_NUM=>48974);

PL/SQL procedure successfully completed.

SQL> 

If the session is disconnected before we stop tracing, tracing will automatically be stopped and upon trying to stop the tracing, we will get the below error

BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>7, SERIAL_NUM=>44); END;

*
ERROR at line 1:
ORA-00030: User session ID does not exist.
ORA-06512: at "SYS.DBMS_MONITOR", line 144
ORA-06512: at line 1

We can also use the DBMS_SYSTEM package to trace the session as below. DBMS_MONITOR explained above gives better control of what we need in terms of tracing

SQL> select username, sid, serial# from v$session where username='SOE';

USERNAME                              SID    SERIAL#
------------------------------ ---------- ----------
SOE                                  1151       6659

SQL> exec sys.dbms_system.set_sql_trace_in_session(1151, 6659, TRUE);

PL/SQL procedure successfully completed.

SQL> exec sys.dbms_system.set_sql_trace_in_session(1151, 6659, FALSE);

PL/SQL procedure successfully completed.

SQL> desc sys.dbms_system
...
...
PROCEDURE SET_SQL_TRACE_IN_SESSION
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SID                            NUMBER                  IN
 SERIAL#                        NUMBER                  IN
 SQL_TRACE                      BOOLEAN                 IN
...
...
SQL> 

So we now conclude with different methods of tracing a session. In the next post, we will take a look at Application tracing methods. Please check this link to learn on Application tracing methods

To convert raw trace file to human readable format, check this link on tkprof 

References: 

DBMS_MONITOR (oracle.com)

General SQL_TRACE / 10046 trace Gathering Examples (Doc ID 1274511.1)

Happy tracing...!!!