Tracing a bad performing query
Generating 10046 trace level 12 for the procedure when it performs well and when it performs poorly for initial analysis.
10046 trace files:
~~~~~~~~~~~~~~~~~~
To gather 10046 trace at the session level:
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>
SQL>select * from dual;
SQL>alter session set events '10046 trace name context off';
then use tkprof for generated .trc file.
The files would be generated under user_dump_dest.
SQL trace 10046 -- analysis of tkprof outputs
SQL trace with event10046 in Oracle database
Tkprof and analysis
Tkprof and analysis
Different levels of tracing
Examples
FAQ:
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?
FAQ:
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?
- 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?
- 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 ?
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
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#
-- To set and identify trace file
ALTER SESSION SET sql_trace=TRUE;
alter session set max_dump_file_size=unlimited;
alter session set tracefile_identifier='Trace10046';
-- To Enable the trace ( find sid and serial# from v$session for issue query )
EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 173, serial_num => 399, waits => TRUE, binds => TRUE);
-- To Disbale
EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id => 173, serial_num =>399);
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?
- 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 ehischn1_ora_33751070_gou_plan1.trc gou_plan1.txt SYS=NO SORT = (prsela,exeela,fcheck)
see more on follow link
Click here
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';
$ 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.
bash-4.2$ 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:
bash-4.2$ 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
bash-3.2$ 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.
Ouput:
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 = 'Rad10046_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.
