Tracing a Database Session

In Oracle, there are several ways to trace a database session. I will share my preferred method, which uses oradebug. Note that this must be executed from the database server, not remotely.

First, we need to specify the type of trace we want. Here are the most effective events we can use:

41051:

• Description: This event is related to lock tracing. It can be used to trace detailed information about locks occurring in the database.
• Usage: Typically used to diagnose lock and resource contention issues.

10046:

• Description: This is one of the most commonly used trace events, known as "SQL trace." It captures details about the execution of SQL statements, including wait events, execution statistics, and other detailed information.
• Usage: Used for detailed performance analysis and SQL diagnostics.
• Levels:
• 1: Basic SQL tracing.
• 4: Includes wait event information.
• 8: Includes bind variable statistics.
• 12: Combination of levels 4 and 8.

10053:

• Description: This event activates tracing for the query optimizer (CBO - Cost-Based Optimizer). It generates a detailed trace about the optimizer’s decisions when choosing execution plans for SQL queries.
• Usage: Primarily used by DBAs and developers to understand and diagnose performance issues related to the optimizer’s choices.

1555:

• Description: This event is related to the "ORA-01555: snapshot too old" error. This error occurs when a query cannot see a consistent version of the data because the necessary undo records have been overwritten.
• Usage: Used to diagnose issues related to the ORA-01555 error and to monitor the conditions causing this error.

In most cases, I use trace to find performance issues, so I prefer the 10046 event at level 12.

After choosing the appropriate method, you need to determine which session you want to trace.

Tracing the Session:

SQL> select p.spid, p.tracefile from gv$session s, gv$process p where s.paddr = p.addr and s.inst_id = p.inst_id and s.sid=&sid;
SQL> oradebug setospid ; -- get that from the previous SQL --
SQL> oradebug tracefile_name; -- it will show you what is your trace file --
SQL> oradebug unlimit;
SQL> oradebug event 10046 trace name context forever, level 12;

If you are struggling to find the right session ID to trace, this script may help you.

Let the user do their work, then turn the trace off using the command below. If the session ends during the process, the trace will end as well.

SQL> oradebug event 10046 trace name context off;

Analyzing The Tracefile

After finishing your trace, you can open the trace file and read it, but it will be difficult to understand. I recommend using another tool to generate a readable report. The tool is called TKPROF and it is installed with your database binaries on your database server.

To run the TKPROF tool and generate a readable report, you need to know the trace file name, which we obtained in the previous steps.

We have a few options for running TKPROF. You can just run it, but I recommend using a few parameters to make it easier to read.

If you just generate the report, it will show all the statements in the order they were executed in the user session. However, when analyzing performance, I want to know which statements took the most time to run and why.

There are many parameters and ways to generate it. For more information, please refer to the official documentation.

Here are the four ways I usually use:

• Regular TKPROF report:

oracle$ tkprof /u01/app/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_8708.trc /home/oracle/working/tarnowski/traces/ORCL_ora_8708.txt 

• TKPROF removing the system statements:

oracle$ tkprof /u01/app/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_8708.trc /home/oracle/working/tarnowski/traces/ORCL_ora_8708.txt sys=no

• Ordered by the query that took the most time - Descending:

oracle$ tkprof /u01/app/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_8708.trc /home/oracle/working/tarnowski/traces/ORCL_ora_8708.txt sys=no sort=exeela

• Adding the explain plan for the queries found in the trace file:

oracle$ tkprof /u01/app/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_8708.trc /home/oracle/working/tarnowski/traces/ORCL_ora_8708.txt sys=no sort=exeela explain=user/password

Here is a summary of each part of the TKPROF report to help you understand it better if you are not familiar with it yet.

PARSE...: Oracle locates the query in the shared pool or generates a new execution plan.
EXECUTE.: Executes the query. This step is empty for SELECT statements.
FETCH...: Retrieves the data, empty for updates but performs the main work for SELECT statements.
Count...: The number of times each action has been carried out.
CPU.....: The amount of CPU time utilized by the query.
ELAPSED.: The total wall clock time taken.
DISK....: The physical I/O operations to the disk.
Query...: Blocks read from the rollback or undo segments.
Current.: Blocks in their current state.
Rows....: The number of rows impacted.

Tracing All The Sessions From a Specific User

Sometimes the app owner or developer is running something in the application side and the session take a few seconds and it's consider too long, but at the same time, is a short time for you to trace the session itself, so you can create a logon trigger to trace all the sessions comming from a specific user.

With that trigger, all the trace files will have an identified in his name, so you just need to open the destination folder of the traces and then find the ones with your identifier. You can easily do this using a grep command.

SQL> CREATE OR REPLACE TRIGGER SET_TRACE AFTER LOGON ON DATABASE
BEGIN
    IF USER IN ('SCOTT') THEN
        EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER=''TRACED_SESSION''';
        EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS=TRUE';
        EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED';
        EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
    END IF;
END;
/

You can also do this way instead:

SQL> CREATE OR REPLACE TRIGGER SET_TRACE 
AFTER LOGON ON DATABASE
BEGIN
  DECLARE
    os_user VARCHAR2(30);
  BEGIN
    SELECT SYS_CONTEXT('USERENV', 'OS_USER') INTO os_user FROM DUAL;
    IF os_user IN ('OS_USER_YOU_WANT_TO_TRACE') THEN
      EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER=''TRACED_SESSION''';
      EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS=TRUE';
      EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED';
      EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
    END IF;
  END;
END;
/

If you want to see the options of the SYS_CONTEXT, please refer to the documentation.

To find the files, you can do it this way:

oracle$ grep -i TRACED_SESSION /u01/app/oracle/diag/rdbms/orcl/ORCL/trace/*.trc

Now you just need to find the right one. You can check the statements inside the trace files or send them to the developer so they can confirm which session is the one you want to analyze.

With that, you can run tkprof on the traces you want.