The quickest way to capture the SQL being processed by a session is to switch or turn on SQL trace or 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. Explaining the contents of the trace file is beyond the scope of this article, but the following sections explain how trace files can be created and processed.
I will skip much about TRACING and we get to talking about the trace file and
TKPROF
What is the use of TKPROF utility
————————————–
The TKPROF is a utility used to convert the Oracle trace file generated by SQL Trace in to a readable format.
TKPROF is a program that you invoke at the operating system command prompt in order to reformat the trace file into a format that is much easier to comprehend. Each SQL statement is displayed in the report, along with counts of how many times it was parsed, executed, and fetched. CPU time, elapsed time, logical reads, physical reads, and rows processed are also reported, along with information about recursion level and misses in the library cache. TKPROF can also optionally include the execution plan for each SQL statement in the report, along with counts of how many rows were processed at each step of the execution plan.
The SQL statements can be listed in a TKPROF report in the order of how much resource they used, if desired. Also, recursive SQL statements issued by the SYS user to manage the data dictionary can be included or excluded, and TKPROF can write SQL statements from the traced session into a spool file.
A knowledge of the Oracle supplied tool, TKPROF, is essential to building or debugging any SQL code that runs in an Oracle database,
whether that code is written in a language such as Power builder, Visual Basic, Pro*C, PL/SQL, or a SQL*Plus script.
TKPROF lets you see what is really happening inside the database, and acts in a post-mortem capacity, rather than the predictive nature of EXPLAIN PLAN. TKPROF shows you the exact number of disk reads, parses, executions, consistent gets, rows processed, CPU time usage and elapsed time for each cursor that was executed in the database.
Demo of How to using TKPROF
1) Identify sql statement to be traced from users or programmers
2) Grant ALTER SESSION TO schema that will execute the statement
sqlplus system/sys@CLASST
grant alter session to scott;
3) Look where trace file will be created and clean it up or note the last or most recent trace file:
sqlplus / as sysdba
show parameter background
NAME TYPE VALUE
———————————— ———– ——————————
background_core_dump string partial
background_dump_dest string /u01/app/oracle/diag/rdbms/cla
sst/CLASST/trace
exit
Note that trace file will be created in: /u01/app/oracle/diag/rdbms/classt/CLASST/trace
3) Connect as user/schema to execute sql statement:
sqlplus scott/tiger@CLASST
4) Ensure that you have a plan table in your schema,
describe plan_table
–If no table exists, create one by running $ORACLE_HOME/rdbms/admin/utlxplan
@?/rdbms/admin/utlxplan.sql
5) Switch or turn on SQL TRACE for the SESSION and Execute SQL statement in question and exit sqlplus:
alter session set sql_trace true;
select * from dept, emp;
exit
6) Get the trace file produced:
cd /u01/app/oracle/diag/rdbms/classt/CLASST/trace
ll *trc
-rw-r—– 1 oracle oinstall 43976 May 13 22:01 CLASST_ora_18525.trc
7) Execute tkprof following format: tkprof input_file output_file sys=no explain=username/password
Ensure that tkprof is in your PATH variable by issuing the unix command :
which tkprof
Expected output: /u01/app/oracle/product/11.2.0/db_1/bin/tkprof
and in case you have multiple versions of Oracle running, ensure that you will be executing the correct version.
tkprof CLASST_ora_18525.trc CLASST_ora_18525._tkprof_output sys=no explain=scott/tiger@CLASST
Aso try:
tkprof CLASST_ora_18525.trc CLASST_ora_18525._tkprof_output sys=no explain=SYSTEM/sys@CLASST
TKPROF will accept the trace file as your input_file parameter, and generate an output file specified in the out_file parameter (ensure that you have write privilege on the designated directory). Now let us go into some of the trace file details. This is where the fun starts. Open the output_file with your favorite editor and examine it.
Review the explained example below before looking at your output file again.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Consider the statement below and then review it’s tkprof output and then explanation following:
This example contains the trace file generated for a single query that was behaving very badly, for something that should have returned information with sub-second response time in an OLTP environment, which was taking over a minute to run. To visualize the impact of this, imagine that this query was executed at least 10 times per hour by every one of 150 users, on a 4 CPU machine. Now you get an idea of just what an important tool this TKPROF is.
********************************************************************************
SELECT
T3.ROW_ID,
T3.MODIFICATION_NUM,
T3.CREATED_BY,
T3.LAST_UPD_BY,
T3.CREATED,
T3.LAST_UPD,
………
T2.LOC,
T3.X_ACTION,
T3.BUILD,
T3.COMMENTS,
T2.CMPT_FLG
FROM
SIEBEL.S_PROD_INT T1,
SIEBEL.S_ORG_EXT T2,
SIEBEL.S_ORG_PROD T3
WHERE
T3.OU_ID = T2.ROW_ID AND
T3.PROD_ID = T1.ROW_ID AND
(T3.PAR_ORG_PROD_ID IS NULL) AND
(T3.X_QUOTE_ID = :1)
ORDER BY
T3.CREATED DESC
call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 39.65 58.48 4071 44375 2 1
——- —— ——– ———- ———- ———- ———- ———-
total 3 39.66 58.48 4071 44375 2 1
Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 325 (JOGRAVE)
Rows Execution Plan
——- —————————————————
0 SELECT STATEMENT GOAL: RULE
1 SORT (ORDER BY)
1 NESTED LOOPS
1 NESTED LOOPS
1780388 TABLE ACCESS (FULL) OF ‘S_ORG_PROD’
1 TABLE ACCESS (BY ROWID) OF ‘S_ORG_EXT’
1 INDEX (UNIQUE SCAN) OF ‘S_ORG_EXT_P1’ (UNIQUE)
1 TABLE ACCESS (BY ROWID) OF ‘S_PROD_INT’
1 INDEX (UNIQUE SCAN) OF ‘S_PROD_INT_P1’ (UNIQUE)
********************************************************************************
Misses in library cache during parse: 0
117 user SQL statements in session.
0 internal SQL statements in session.
117 SQL statements in session.
71 statements EXPLAINed in this session.
********************************************************************************
Trace file: ora_14177.trc
Trace file compatibility: 7.03.02
Sort options: default
1 session in tracefile.
117 user SQL statements in trace file.
0 internal SQL statements in trace file.
117 SQL statements in trace file.
71 unique SQL statements in trace file.
71 SQL statements EXPLAINed using schema:
SIEBEL.prof$plan_table
Default table was used.
Table was created.
table was dropped.
5763 lines in trace file.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Explanation of above tkprof output
From the above we can see the following:
The statement was parsed once
The statement was executed once
It took 58.48 seconds inside the database to run
Of that time, 39.66 seconds was CPU time
It performed 4071 disk reads (blocks read from disk), and 2 consistent gets
It read a total of 44,375 rows and returned 1 row to the calling environment.
From the EXPLAIN PLAN output, we see that the Rule Based Optimizer was used and that the user id (username from DBA_USERS) was ‘JOGRAVE’
The query did a full table scan on the S_ORG_PROD table, which contains 1,78 million rows
It then did a unique scan of the S_ORG_EXT_P1 index defined for the S_ORG_EXT table, and read the S_ORG_EXT table by rowid, obtained from the unique index scan.
It then did a NESTED loop join of these tables.
It then read the S_PROD_INT_P1 index (which is the unique index associated with the primary key) for table S_PROD_INT, then joined the results of this to the first result set it already had for the previous two tables, by way of NESTED LOOP join.
It then sorted the resultant set (1 row), as specified in the ORDER BY clause.
Clearly, this statement is in need of tuning and using TKPROF, the developer now has proof of what the statement is doing inside the DB.
TKPROF relies on a trace file being generated. In order for the trace file to be generated, the init.ora parameter TIMED_STATISTICS must be set to true in the database on startup time. This tracing feature incurs a very small performance hit (in the order of about 1%), for the sessions it traces. There is another parameter called SQL_TRACE which can be set to true in the database, in which every single command of every single non-BACKGROUND session will be traced. This is a very high overhead activity and can slow down the database performance by a factor of between 30 to 40 %, and this action is suggested only for diagnostics purposes, with a small number of users. With a high user count, the engine would be spewing out trace files all over the user_dump_dest directory.
To generate a trace file for one’s own session, issue the command: alter session set sql_trace true;
To generate a trace file for another session in the DB, first obtain the SID and SERIAL# values from the v$session view for the session that you want to trace. Then join the row from v$session to v$process, and get the shadow process id for the session :
col log_tim for a15
set verify off
accept usr prompt ‘Enter username : ‘
REM enter the user name with caps before executing the next statement:
select a.osuser, a.username, a.sid, a.serial#, to_char(a.logon_time,’DAY HH24:MI:SS’) log_tim,b.spid
from v$session a, v$process b where a.paddr=b.addr and a.username=’&&usr’ ;
The reason we get the spid, is because Oracle will start to generate a trace file called ora_12345.trc in user_dump_dest, where 12345 is the spid value of v$process for the session.
Now that you have the SID and SERIAL# values, you can turn on tracing in one of two ways, using the DBMS_SYSTEM Oracle supplied package.
SQL > execute sys.dbms_system.set_sql_trace_in_session(SID, SERIAL#,true);
where values for SID and SERIAL# are retrieved by the query above. In order to make sure that the trace file is readable by any user (owned by oracle with group id DBA), set the init.ora parameter
_trace_files_public=true
The other way is to use DBMS_SYSTEM.SET_EV, this will let you see the contents of the bind variables too.
Now that tracing has been turned on, run whatever it is that you are wanting tracing information on, when done execute the dbms_system.set_sql_trace_in_session with a ‘false’ parameter as the 3rd argument, or simply log out of the database.
Now identify the trace file in the user_dump_dest directory, this is the file to be fed as input to TKPROF.
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
See more about
SQL trace, 10046, trcsess and tkprof in Oracle
at
See Oracle Docs at https://docs.oracle.com/cd/B10500_01/server.920/a96533/sqltrace.htm : Using SQL Trace and TKPROF
0 Comments