| Oracle7 Server Tuning |  Library |
 Product |
 Contents |
 Index |
| Oracle7 Server Tuning | Library |
Product |
Contents |
Index |
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.
Before enabling the SQL trace facility, you should:
ALTER SESSION SET SQL_TRACE = TRUE;
Alternatively, you can enable the SQL trace facility for your session by using the DBMS_SESSION.SET_SQL_TRACE procedure.
To disable the SQL trace facility for your session, enter:
ALTER SESSION SET SQL_TRACE = FALSE;
The SQL trace facility is automatically disabled for your session when your application disconnects from Oracle.
Note: You may need to modify your application to contain the ALTER SESSION command. For example, to issue the ALTER SESSION command in Oracle Forms, invoke Oracle Forms using the -s option, or invoke Oracle Forms (Design) using the statistics option. For more information on Oracle Forms, see the Oracle Forms Reference manual.
This procedure requires the session ID and serial number of the user session in question, which you can obtain from the V$SESSION view. In the WHERE clause you can specify sessions by referencing the value of the OSUSER, USERNAME, or PROGRAM column in V$SESSION. For example, the following Server Manager line mode session obtains the session ID and serial number for the operating system user jausten and then enables SQL trace for that user's session:
SVRMGR> SELECT sid, serial#, osuser
2> FROM v$session
3> WHERE osuser = 'jausten';
SID SERIAL# OSUSER
---------- ---------- ---------------
8 12 jausten
1 row selected.
SVRMGR> EXECUTE dbms_system.set_sql_trace_in_session(8,12,TRUE);
Statement processed.
To enable SQL trace in stored procedures, use this SQL statement:
DBMS_SESSION.SET_SQL_TRACE (TRUE);
Once the SQL trace facility has been enabled for the instance, you can disable it for an individual session by entering:
ALTER SESSION SET SQL_TRACE = FALSE;
Once the SQL trace facility has generated a number of trace files, you can:
SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno;
call count cpu elapsed disk query current rows
---- ------- ------- --------- -------- -------- ------- ------
Parse 1 0.16 0.29 3 13 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.03 0.26 2 2 4 14
Misses in library cache during parse: 1
Parsing user id: (8) SCOTT
Rows Execution Plan
------- ---------------------------------------------------
14 MERGE JOIN
4 SORT JOIN
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT JOIN
14 TABLE ACCESS (FULL) OF 'EMP'
For this statement, TKPROF output includes the following information:
If you invoke TKPROF with no arguments, online help is displayed.
Use the following arguments with TKPROF:
TKPROF ora53269.trc ora 53269.prf
SORT = (PRSDSK, EXEDSK, FCHDSK)
PRINT = 10
TKPROF DLSUN12_JANE_FG_SVRMGR_007.TRC OUTPUTA.PRF
EXPLAIN=SCOTT/TIGER TABLE=SCOTT.TEMP_PLAN_TABLE_A INSERT=STOREA.SQL SYS=NO SORT=(EXECPU,FCHCPU)
This example is likely to be longer than a single line on your screen and you may have to use continuation characters, depending on your operating system.
Note the other parameters in this example:
|
rows
|
Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.
|
If recursive calls occur while the SQL trace facility is enabled, TKPROF produces statistics for the recursive SQL statements and clearly marks them as recursive SQL statements in the output file. Note that the statistics for a recursive SQL statement are included in the listing for that statement, not in the listing for the SQL statement that caused the recursive call. So when you are calculating the total resources required to process a SQL statement, you should consider the statistics for that statement as well as those for recursive calls caused by that statement. Note that setting the SYS command line parameter to NO suppresses the listing of recursive calls in the output file.
See Also: Chapter 20, "The EXPLAIN PLAN Command" for more information on interpreting execution plans.
SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno;
call count cpu elapsed disk query current rows
---- ------- ------- --------- -------- -------- ------- ------
Parse 11 0.08 0.18 0 0 0 0
Execute 11 0.23 0.66 0 3 6 2
Fetch 35 6.70 6.83 100 12326 2 824 ------------------------------------------------------------------
total 57 7.01 7.67 100 12329 8 826
Misses in library cache during parse: 0
10 user SQL statements in session.
0 internal SQL statements in session.
10 SQL statements in session.
If it is acceptable to expend 7.01 CPU seconds to insert, update or delete 2 rows and to retrieve 824 rows, then you need not look any further at this trace output. In fact, a major use of TKPROF reports in a tuning exercise is to eliminate processes from the detailed tuning phase.
You can also see from this summary that 1 unnecessary parse call was made (because there were more parse calls than SQL statements) and that array fetch operations were performed. (You know this because more rows were fetched than there were fetches performed.)
Finally, you can see that very little physical I/O was performed; this is suspicious and probably means that the same database blocks were being continually re-visited.
Having established that the process has used excessive resource, the next step is to discover which SQL statements are the culprits. Normally only a small percentage of the SQL statements in any process need to be tuned, and these are the ones which use the greatest resource.
The examples which follow were all produced with TIMED_STATISTICS=TRUE. However, with the exception of locking problems and inefficient PL/SQL loops, neither the CPU nor the elapsed time are necessary to find the problem statements. The key is the number of block visits both query (that is, subject to read consistency) and current (not subject to read consistency). Segment headers and blocks which are going to be updated are always acquired in current mode, but all query and sub-query processing requests the data in query mode. These are precisely the same measures as the instance statistics consistent gets and db block gets.
The SQL parsed as SYS is recursive SQL used to maintain the dictionary cache, and is not normally of great benefit; if the number of internal SQL statements looks high it may be worth checking to see what has been going on. (There may be excessive space management overhead.)
If you have already created an output table for previously collected statistics and you want to add new statistics to the existing table, remove the CREATE TABLE statement from the script. The script will then insert the new rows into the existing table.
If you have created multiple output tables, perhaps to store statistics from different databases in different tables, edit the CREATE TABLE and INSERT statements to change the name of the output table.
CREATE TABLE tkprof_table
(date_of_insert DATE,
cursor_num NUMBER,
depth NUMBER,
user_id NUMBER,
parse_cnt NUMBER,
parse_cpu NUMBER,
parse_elap NUMBER,
parse_disk NUMBER,
parse_query NUMBER,
parse_current NUMBER,
parse_miss NUMBER,
exe_count NUMBER,
exe_cpu NUMBER,
exe_elap NUMBER,
exe_disk NUMBER,
exe_query NUMBER,
exe_current NUMBER,
exe_miss NUMBER,
exe_rows NUMBER,
fetch_count NUMBER,
fetch_cpu NUMBER,
fetch_elap NUMBER,
fetch_disk NUMBER,
fetch_query NUMBER,
fetch_current NUMBER,
fetch_rows NUMBER,
clock_ticks NUMBER,
sql_statement LONG)
These columns help you identify a row of statistics:
The following query returns the statistics from the output table. These statistics correspond to the formatted output shown in the section "Step 4: Interpreting TKPROF Output" on page 21-12.
SELECT * FROM tkprof_table;
DATE_OF_INSERT CURSOR_NUM DEPTH USER_ID PARSE_CNT PARSE_CPU PARSE_ELAP
-------------- ---------- ----- ------- --------- --------- ----------
27-OCT-1993 1 0 8 1 16 29
PARSE_DISK PARSE_QUERY PARSE_CURRENT PARSE_MISS EXE_COUNT EXE_CPU
---------- ----------- ------------- ---------- --------- -------
3 13 0 1 1 0
EXE_ELAP EXE_DISK EXE_QUERY EXE_CURRENT EXE_MISS EXE_ROWS FETCH_COUNT
-------- -------- --------- ----------- -------- -------- -----------
0 0 0 0 0 0 1
FETCH_CPU FETCH_ELAP FETCH_DISK FETCH_QUERY FETCH_CURRENT FETCH_ROWS
--------- ---------- ---------- ----------- ------------- ----------
3 26 2 2 4 14
SQL_STATEMENT
---------------------------------------------------------------------
SELECT * FROM EMP, DEPT WHERE EMP.DEPTNO = DEPT.DEPTNO
If certain parameters are not specified by the report user, the query uses bind variables which have been set to "%" to cause the LIKE clauses in the query to operate as if they were not there. It would be more efficient to run a query in which these clauses are not present.
Note: TKPROF cannot tell the TYPE of the bind variables simply by looking at the text of the SQL statement. It assumes that TYPE is CHARACTER; if this is not the case, you should put appropriate type conversions in the SQL statement.
Cases like this are not normally repeatable: if the process were run again, it is unlikely that another transaction would interact with it in the same way.
select NAME_ID
from CQ_NAMES where NAME = 'FLOOR'
call count cpu elapsed disk query current rows
---- ----- --- ------- ---- ----- ------- ----
Parse 1 0.11 0.21 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.15 0.24 4 150 0 1
Misses in library cache during parse: 1
Parsing user id: 13 (DJONES)
Rows Execution Plan
---- --------- ----
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON_UNIQUE)
select NAME_ID
from CQ_NAMES where NAME = 'FLOOR'
call count cpu elapsed disk query current rows
-------- ------- -------- --------- -------- -------- ------- ----------
Parse 1 0.04 0.12 0 0 0 0
Execute 1 0.01 0.01 0 0 0 0
Fetch 1 0.32 0.32 38 44 3 1
Misses in library cache during parse: 0
Parsing user id: 13 (JAUSTEN
Rows Execution Plan
------- ---------------------------------------------------
0 SELECTSTATEMENT
3519 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
0 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)
Two statistics suggest that the query may have been executed via a full table scan. These statistics are the current mode block visits, plus the number of rows originating from the Table Access row source in the execution plan. The explanation is that the required index was built after the trace file had been produced, but before TKPROF had been run.
update CQ_NAMES set ATTRIBUTES = lower(ATTRIBUTES)
where ATTRIBUTES = :att
call count cpu elapsed disk query current rows
-------- ------- -------- --------- -------- -------- ------- ----------
Parse 1 0.08 0.24 0 0 0 0
Execute 1 0.63 19.63 33 526 13 7
Fetch 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Parsing user id: 13 (JAUSTEN)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT
3519 TABLE ACCESS (FULL) OF 'CQ_NAMES'
Again, the answer is interference from another transaction. In this case another transaction held a shared lock on the table CQ_NAMES for several seconds before and after the update was issued. It takes a fair amount of experience to diagnose that interference effects are occurring. Comparative data is essential when the interference is only contributing a short delay (or a small increase in block visits in the previous example). On the other hand, if the interference is only contributing a modest overhead, and the statement is essentially efficient, its statistics may never have to be subjected to analysis.
You may need to inspect the raw trace file to see exactly where the resource is being expended. The entries for recursive SQL follow the PARSING IN CURSOR entry for the user's statement. Within the trace file, the order is less easily defined.
select NAME_ID
One of the marked features of this correct version is that the parse call took 10 milliseconds of both elapsed and CPU time, but the query apparently took no time at all to execute and no time at all to perform the fetch. In fact, no parse took place because the query was already available in parsed form within the shared SQL area. These anomalies are due to the clock tick of 10 msec being too long to reliably record simple and efficient queries.
Copyright (c) Oracle Corporation 1979, 1996. All rights reserved.
Trace file: v73_ora_2758.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
********************************************************************************
The following statement encountered a error during parse:
select deptno, avg(sal) from emp e group by deptno
having exists (select deptno from dept
where dept.deptno = e.deptno
and dept.budget > avg(e.sal)) order by 1
Error encountered: ORA-00904
********************************************************************************
alter session set sql_trace = true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.15 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.15 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
.
.
.
********************************************************************************
select emp.ename, dept.dname from emp, dept
where emp.deptno = dept.deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.12 0.14 2 0 2 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 2 2 4 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.12 0.14 4 2 6 14
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
select a.ename name, b.ename manager from emp a, emp b
where a.mgr = b.empno(+)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 54 2 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 1 54 2 14
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
13 NESTED LOOPS (OUTER)
14 TABLE ACCESS (FULL) OF 'EMP'
13 TABLE ACCESS (BY ROWID) OF 'EMP'
26 INDEX (RANGE SCAN) OF 'EMP_IND' (NON-UNIQUE)
.
.
.
********************************************************************************
select ename,job,sal
from emp
where sal =
(select max(sal)
from emp)
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 1 0.00 0.00 0 16 4 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 16 4 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 FILTER
14 TABLE ACCESS (FULL) OF 'EMP'
14 SORT (AGGREGATE)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
select deptno
from emp
where job = 'clerk'
group by deptno
having count(*) >= 2
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 1 0.00 0.00 0 1 2 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 2 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 FILTER
0 SORT (GROUP BY)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
select dept.deptno,dname,job,ename
from dept,emp
where dept.deptno = emp.deptno(+)
order by dept.deptno
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 1 0.00 0.00 0 2 4 15
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 4 15
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN (OUTER)
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
select grade,job,ename,sal
from emp,salgrade
where sal between losal and hisal
order by grade,job
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.08 2 18 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 11 12 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.07 0.09 3 29 13 14
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 SORT (ORDER BY)
14 NESTED LOOPS
5 TABLE ACCESS (FULL) OF 'SALGRADE'
70 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
select lpad(' ',level*2)||ename org_chart,level,empno,mgr,job,deptno
from emp
connect by prior empno = mgr
start with ename = 'clark'
or ename = 'blake'
order by deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 0 1 2 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 0 1 2 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 SORT (ORDER BY)
0 CONNECT BY
14 TABLE ACCESS (FULL) OF 'EMP'
0 TABLE ACCESS (BY ROWID) OF 'EMP'
0 TABLE ACCESS (FULL) OF 'EMP'
********************************************************************************
create table tkoptkp (a number, b number)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.01 1 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.01 1 0 1 0
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 CREATE TABLE STATEMENT GOAL: CHOOSE
.
.
.
********************************************************************************
insert into tkoptkp
values
(1,1)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.09 0 0 0 0
Execute 1 0.01 0.20 2 2 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.08 0.29 2 2 3 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE
.
.
.
********************************************************************************
insert into tkoptkp select * from tkoptkp
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.02 0.04 0 2 3 12
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.02 0.04 0 2 3 12
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE
12 TABLE ACCESS (FULL) OF 'TKOPTKP'
********************************************************************************
select *
from
tkoptkp where a > 2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 1 2 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.01 0.01 0 1 2 12
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
24 TABLE ACCESS (FULL) OF 'TKOPTKP'
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.40 0.53 30 182 3 0
Execute 19 0.05 0.41 3 7 10 16
Fetch 12 0.05 0.06 4 105 66 78
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 49 0.50 1.00 37 294 79 94
Misses in library cache during parse: 18
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 69 0.49 0.60 9 12 8 0
Execute 103 0.13 0.54 0 0 0 0
Fetch 213 0.12 0.27 40 435 0 162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 385 0.74 1.41 49 447 8 162
Misses in library cache during parse: 13
19 user SQL statements in session.
69 internal SQL statements in session.
88 SQL statements in session.
17 statements EXPLAINed in this session.
********************************************************************************
Trace file: v73_ora_2758.trc
Trace file compatibility: 7.03.02
Sort options: default
1 session in tracefile.
19 user SQL statements in trace file.
69 internal SQL statements in trace file.
88 SQL statements in trace file.
41 unique SQL statements in trace file.
17 SQL statements EXPLAINed using schema:
SCOTT.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
1017 lines in trace file.
|
Prev Next |
 Copyright © 1996 Oracle Corporation. All Rights Reserved. |
Library |
Product |
Contents |
Index |