SQL trace 10046 -- analysis of tkprof outputs

~ SQL trace with event10046 in Oracle database
~ tkprof and analysis
~ Different levels of tracing
~ Examples

We will discuss following topics:

1) What is sql tracing?
2) Why 10046?
3) Why level 8 or 12?
4) How to use?
5) Where will be the xxx.trc file ?
6) How to user tkprof xxx.trc file?
7) How to analyze tkprof output file?
8) Any performance issue during sql trace?

1) What is sql tracing?
Ans:

• The SQL Trace facility provides performance information on individual SQL statements in bottlenect situations.
• It generates the following statistics for each statement
• Parse, execute, and fetch counts
• CPU and elapsed times
• Physical reads and logical reads
• Number of rows processed
• Username under which each parse occurred
• Each commit and rollback etc.
• Can enable the SQL Trace facility for a session or for an instance. When the SQL Trace facility is enabled, performance statistics for all SQL statements executed in a user session or in the instance are placed into trace files.
• The additional overhead of running the SQL Trace facility against an application with performance problems is normally insignificant compared with the inherent overhead caused by the application's inefficiency.

Note:
Try to enable SQL Trace only for statistics collection and on specific sessions. If you must enable the facility on an entire production environment, then you can minimize performance impact with the following:
    Maintain at least 25% idle CPU capacity.
    Maintain adequate disk space for the USER_DUMP_DEST location.
    Stripe disk space over sufficient disks.

2) Why 10046?
Ans:

• This is oracle tracing event. ( see details : Click here)
• The quickest way to capture the SQL being processed by a session is to switch on SQL trace
• Set the 10046 event for a representative period of time. The resulting trace files can be read in their raw state or translated using the tkprof utility.

3) Why level 8 ?
Ans:
Various kinds of levels are there. Here are use of various events during tracing.
    1 - Standard trace output including parsing, executes and fetches plus more
    2 - same as Level 1
    4 - Level 1 + Bind Variables
    8 - Level 1 + Waits
    12 - Level 1 + Bind Variables & Waits

4) How to use?
-- When reoccur the issue and trace the same. Basically this is not useful when your system hung or slow. For that you can use "hang analyzer" or "oradebug". Next to this "oradebug" examples given.
Ans:
SQL> ALTER SESSION SET tracefile_identifier = 'gou_plan1';
SQL>alter session set timed_statistics = true;
SQL>alter session set statistics_level=all;
SQL>alter session set max_dump_file_size = unlimited;
SQL>alter session set events '10046 trace name context forever,level 12';
SQL><run the problem query> / wait for 3 to 5 minutes (in prod) / do some transaction/ problematic query (in SIT/DEV/UAT)
SQL>select * from dual;
SQL>alter session set events '10046 trace name context off';

-- With sid and serial#
You can SID and SERIAL has of the session from v$ session or v$session_wait or AWR/ ASH reports as well. Using sid and searl# find out OS pid and you can trace it via "oradebug".

SQL> CONN sys/password AS SYSDBA;   -- User must have SYSDBA.
SQL> ORADEBUG SETMYPID;           -- Debug current session.
SQL> ORADEBUG SETOSPID 1234; -- Debug session with the specified OS process.
SQL> ORADEBUG SETORAPID 123456; -- Debug session with the specified Oracle process ID.
SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
SQL> ORADEBUG TRACEFILE_NAME;     -- Display the current trace file.
SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;

5) Where will be the xxx.trc file ?

Ans:
xxx.trc file will be generated in user_dump_dest location of the DB server.
Example:
SQL> show parameter user_dump_dest;

NAME              TYPE        VALUE------------ ----------- ------------------------------user_dump_dest    string       /u01/app/oracle/diag/rdbms/prddb/PRDDB1/trace

6) How to user 'tkprof' xxx.trc file?
Ans:

• TKPROF accepts as input a trace file produced by the SQL Trace facility, and it produces a formatted output file.
• TKPROF can also be used to generate execution plans.

After the SQL Trace facility has generated a number of trace files, you can:

• Run TKPROF on each individual trace file, producing a number of formatted output files, one for each session.
• Concatenate the trace files, and then run TKPROF on the result to produce a formatted output file for the entire instance.
• TKPROF does not report COMMITs and ROLLBACKs that are recorded in the trace file.

Syntax:
$ TKPROF <trace_file_name> <output_file_name>
[explain=<user/password> [table=<schema.table_name>]]
[print=<integer>]            -- list only the first nth SQL statements
[aggregate=<yes|no>
[insert=<file_name>]     -- list SQL statements and data inside INSERT statements
[sys=<no>]                   -- TKPROF does not list SQL statements run as user SYS
[record=<file_name>]     -- record non-recursive statements in the trace file
[waits=<yes|no>]         -- record summary of for wait events in the trace file
[sort=<sort_options_list>]     -- zero or more of the listed sort options

Sort options:
prsela : elapsed time parsing
exeela: elapsed time executing
fchela: elapsed time fetching
fchcpu:cpu time spent fetching
etc.

Example: 
$ tkprof prddb_ora_33751070_gou_plan1.trc gou_plan1.txt SYS=NO SORT =prsela,exeela,fchela

see more on follow link Click here

Sample Examples:

$ pwd
/u01/app/oracle/diag/rdbms/prddb/PRDDB1/trace
bash-4.2$ sqlplus / as sysdba
SQL> ALTER SESSION SET tracefile_identifier = 'gou_plan1';
Session altered.

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
Session altered.

SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
Session altered.

$ tkprof    PRDDB1_ora_14680516_gou_plan1.trc gou_plan.txt
TKPROF: Release 11.2.0.3.0 - Development on Mon Nov 18 18:25:50 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Output:
$ cat gou_plan.txt
TKPROF: Release 11.2.0.3.0 - Development on Mon Nov 18 18:25:50 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.
Trace file: PRDDB1_ora_14680516_gou_plan1.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
*******************************************************************************
SQL ID: 0kjg1c2g4gdcr Plan Hash: 0
ALTER SESSION SET EVENTS '10046 trace name context off'

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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: SYS
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1      118.64        118.64

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
    1  user  SQL statements in session.
    0  internal SQL statements in session.
    1  SQL statements in session.
********************************************************************************
Trace file: PRDDB1_ora_14680516_gou_plan1.trc
Trace file compatibility: 11.1.0.7
Sort options: default
       1  session in tracefile.
       1  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       1  SQL statements in trace file.
       1  unique SQL statements in trace file.
      34  lines in trace file.
       0  elapsed seconds in trace file.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Example:2

ALTER SESSION SET tracefile_identifier = 'plan10046_lev12';
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
--wait some time
ALTER SESSION SET EVENTS '10046 trace name context off';
----- go to user_dump_dest and find the trace file

$ tkprof PRDDB2_ora_40829114_plan10046_lev12.trc plan10046_lev12.txt sort = exeela, prsela,fchela
TKPROF: Release 11.2.0.3.0 - Development on Tue Nov 19 11:09:02 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Out put:

bash-3.2$ cat plan10046_lev12.txt
TKPROF: Release 11.2.0.3.0 - Development on Tue Nov 19 11:09:02 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.
Trace file: PRDDB2_ora_40829114_plan10046_lev12.trc
Sort options: exeela  prsela  fchela 
********************************************************************************
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: 0kjg1c2g4gdcr Plan Hash: 0
ALTER SESSION SET EVENTS '10046 trace name context off'
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: SYS
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1      112.60        112.60

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0
Misses in library cache during parse: 0

    1  user  SQL statements in session.
    0  internal SQL statements in session.
    1  SQL statements in session.
********************************************************************************
Trace file: ehischn2_ora_40829114_plan10046_lev12.trc
Trace file compatibility: 11.1.0.7
Sort options: exeela  prsela  fchela 
       1  session in tracefile.
       1  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       1  SQL statements in trace file.
       1  unique SQL statements in trace file.
      34  lines in trace file.
       0  elapsed seconds in trace file.

Example:3

SQL>ALTER SESSION SET tracefile_identifier = 'Example10046_lev12';
SQL>ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
--wait some time
SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

7) How to analyze tkprof outputs:
Ans:
The SQL Trace facility provides performance information on individual SQL statements. It generates the following statistics for each statement:

•Parse, execute, and fetch counts
•CPU and elapsed times
•Physical reads and logical reads
•Number of rows processed
•Misses on the library cache
•Username under which each parse occurred
•Each commit and rollback
•Wait event data for each SQL statement, and a summary for each trace file

8) Any performance issue during sql trace?

Caution : sql trace

Although it is possible to enable the SQL Trace facility for a session or for an instance, it is recommended that you use the DBMS_SESSION or DBMS_MONITOR packages instead. When the SQL Trace facility is enabled for a session or for an instance, performance statistics for all SQL statements executed in a user session or in the instance are placed into trace files. Using the SQL Trace facility can have a severe performance impact and may result in increased system overhead, excessive CPU usage, and inadequate disk space.