Have you ever got stucked up in a long running job ? Do you want to know the behaviour of each sql you are writing ? how the execution path of a sql is determined ? Do you want to know the most time consuming sql statement in your long running procedure or job ? Do you want to know how much time is being spent for cpu cyles, disk acces ? where is the root problem of an query ? on What wait event oracle is waiting ?
For all your question on simple answer is Oracle 10046 Trace. Oracle trace Sql event traces the sql that a user session executes giving diagnostics information, which is useful for general troubleshooting and performance tuning. Oracle 10046 trace is a powerful platform to identify the most problematic sql and how it is behaving with in the oracle environment. With Oracle 10046 trace oracle is capable of providing detailed information that can be used to locate an error or to identify and resolve Performance problems. Oracle 10046 Trace itself consumes memory as well effects the performance of jobs you want to test it. Never run a oracle trace in a production system.To avoid this Oracle has introduced different trace levels based on the information needed. The other trace levels available with oracle 10046 trace are level 1, level 4, level 8, level 12.A 10046 deep trace (level 12) shows exactly how the database is processing a query, the events the system is waiting on and how much time it spends waiting for a specific event.You can enable the tracing or disable it at different phases of a complex job and it is clearly possible to identify a performance issue.
When implementing a 10046 trace, the best approach is to capture the trace stats only for the Query most needed. To do this you can open a new session,turn the trace on, run the query , deactivate the trace in that session and close that session. However it is also possible to capture the oracle 10046 trace stats for already a long running session.
Oracle 10046 trace event works in all Oracle Versions 10g, oracle 9i, oracle 8i. Oracle 10g has introduced a new package called dbms_monitor to get the diagnostics information similar to 10046 trace event which is helpfule in shared server.
Trace levels
Level 1 - Standard sql trace, nO wait events, no bind variables tracking.All the activities are traced until the end of the session.
Level 4 - In addition to the level 1 tracing , level 4 tracks all the values of the bind variables used in the pl/sql Programs.The code displays these bind variables as: b1, etc. When level4 is activated, the substituted value for the bind variable is displayed in the trace file.
alter session set events ‘10046 trace name context forever, level 4’;
Level 8 - In addition to the level 1 tracing, level 8 displays all the system wait events for this session.
alter session set events ‘10046 trace name context forever, level 8’;
Level 12 - In addtion to the level1, level 4 and level 8 is tracked in level 12. (i.e) tracing in addition to both bind variable substitution and database wait events. A level 12 trace is used for performance issues.
alter session set events ‘10046 trace name context forever, level 12’;
Steps for tracing a session
1. Start a new session by starting sql* plus
SQL> alter session set timeD_statistics=TRUE;
Session altered.
4. Set the max_dump_file_size to unlimited So that your trace is not incomplete and have necessary information. max_dump_file_size is the maximum trace file size that oracle can accomodate.
SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE=<you can use UNLIMITED keyword or specify the size in bytes >;
Session altered.
5. All ther trace files would be directed to the same directory. So it would be difficult to identify your current session’s trace file. Give an identification suffix to your trace file.
SQl> alter session set TRACEFILE_IDENTIFIER = 'PRAVEEN';
Session altered.
6. Turn the oracle 10046 trace event on for your current session for the respective level you want to trace (level 4, level 8, level 12).
SQL> alter session set events '10046 trace name context forever, level 12';
ERROR:
ORA-01031: insufficient privileges
So what happened in the above scenario , am i not having neccessary previliges to alter a session. Then if so how can the above statements like alter session set timed_statistics=true are working perfectly. So i have traced around the net for the necessary information, but not able to find it out. finally i came to know that first when alter session command was introduced, there is no alter session privilege. So oracle has realized the importance and security of trace events and introduced a privilege called “alter session” which is required to trace not only 10046 trace events and also other events.
So what i did is
logged in as sys..
SQL> Grant alter session to praveen;
logged in as praveen..
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
7. For simple understanding i am just entering a simple query
SQL> SELECT * FROM COMP_SCRIP_MAP;-----data--------------------
8. Turn of the oracle trace with the following statement
SQL> alter session set events '10046 trace name context off';
Session altered.
9. Query Execution is over, trace file is generated, then where to look for your trace file. Usually user trace files are generated in the directory specified by the user_dump_dest parameter in init.ora or spfile.
SQL> select value from v$parameter where name='user_dump_dest';
10. select the value from the above query and change to that directory in your operating system.
xx_ora_2844_praveen.trc
11. Find the correct trace file by giving the following command in unix prompt.
find . -name "*PRAVEEN*" -print
12. The trace file consists of very detailed information which is quite difficult to understand for us. To pack the trace file and analyze things in it and present it in a user understandable format a tool called tkprof is used.
at the unix prompt type
tkprof xx_ora_2844_praveen.trc
output-file can be any name and can be pointed to your home directory.
here is part of the formatted trace file by tkprof for the above query.
SELECT *
FROM
COMP_SCRIP_MAP
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.09 0.15 6 218 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 36 0.00 0.07 6 42 0 526
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 38 0.09 0.23 12 260 0 526
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 36
Rows Row Source Operation
------- ---------------------------------------------------
526 TABLE ACCESS FULL COMP_SCRIP_MAP (cr=42 pr=6 pw=0 time=51951 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 36 0.00 0.00
db file sequential read 1 0.03 0.03
db file scattered read 1 0.00 0.00
SQL*Net message from client 36 0.32 9.33
********************************************************************************
How to study the trace file will be explained in coming posts