9.3 SQL Trace and TKPROF
|
| < Day Day Up > |
|
SQL Trace causes trace files to be produced by Oracle Database. Various items of interest are generated into trace files. This information comprises details of CPU and I/O needs plus parsing and execution information, processed rows, commits, and rollbacks. The output in trace files is more or less impossible to interpret by hand. TKPROF is a formatting utility which is used to format trace file output into easily readable output. TKPROF can also be used to produce EXPLAIN PLAN query plans and store past output from statistics collections in trace files, into a file called TKPROF_TABLE.
9.3.1 Setting up SQL Trace
SQL Trace can be configured for instance-level use or for a session, for a session either within a current open session or from one session to another. Setting instance-wide tracing can cause serious performance problems. It is better for performance to enable tracing only from a current session or for a specific session. Not using instance-wide tracing can miss a lot of useful information. I am using instance-level tracing since I am not working on a production server database. Start by setting the TIMED_STATISTICS, TIMED_OS_STATISTICS, and MAX_DUMP_FILE_SIZE parameters.
TIMED_STATISTICS = TRUE TIMED_OS_STATISTICS = 5 MAX_DUMP_FILE_SIZE = 1M
The effect on performance of setting the TIMED_STATISTICS parameter is negligible. The parameters previously shown enable collection of statistics including CPU and I/O statistics. TIMED_STATISTICS writes information to both trace files plus the V$SYSSTATS and V$SESSSTATS performance views. TIMED_OS_STATISTICS is a timing mechanism for statistics collection, triggering system statistics collection periodically.
The MAX_DUMP_FILE_SIZE parameter will truncate each trace file in the USER_DUMP_DEST directory, the default target directory for trace files, usually the $ORACLE_BASE/admin/$ORACLE_SID/ udump directory.
Next set the SQL_TRACE parameter to switch on SQL Trace. The TRACE_ENABLED parameter could also be set to TRUE but we will avoid that. Setting TRACE_ENABLED tends to produce copious amounts of detail, more relevant to Oracle support personnel than anything else.
SQL_TRACE = TRUE
Trace files contain generated statistics. In past versions of Oracle trace levels could be set. Oracle9i Database has a new parameter called STATISTICS_LEVEL which can be set to BASIC, TYPICAL, or ALL. The default is TYPICAL. Setting ALL would incur significant overhead and a noticeable effect on performance. In my database I will set the STATISTICS_LEVEL parameter to ALL to gather as much information as possible. Note that setting this parameter to ALL automatically sets the TIMED_OS_STATISTICS parameter to 5.
STATISTICS_LEVEL = ALL
Session-Level Tracing
Specific sessions can be traced. Tracing at the session level can help to remove tracing overhead from the database in general and focus on a specific session. Personally I have never seen the value in using the session level of tracing. There is far too much information produced. There are easier ways of tracking down problems than using session-level tracing. This command traces the current session. Tracing a specific session may be most applicable to tracking down some really nasty SQL code such as in a pre-release application, or one which should not have been released, or perhaps in an ad hoc SQL environment.
ALTER SESSION SET SQL_TRACE = TRUE;
This command will trace a session other than the current session, someone else's session.
DBMS_SYSTEM_SET_SQL_TRACE_IN SESSION(SID, SERIAL#, TRUE);
Finding Trace Files
One of the biggest problems with trace files is finding them. Many files can be generated. You could find the files applicable to specific processes by including tags in your SQL code such as SELECT 'my trace file' FROM DUAL; or by checking datestamps in the operating system. Typically a trace file is named in the following format:
$ORACLE_SID_ora_<pid>.trc
"pid" represents the process ID of the process which generated the trace file. The process ID can be found with the following query, which finds the process identifier using the process and session addresses and the session auditing identifier as the session identifier.
SELECT spid FROM v$process WHERE addr = (SELECT paddr FROM v$session WHERE audsid = USERENV('sessionid'));
9.3.2 Using SQL Trace
So the next logical step is to make use of SQL Trace. I have now set up my Oracle Database configuration parameter file (init.ora) with various parameter changes.
TIMED_STATISTICS = TRUE TIMED_OS_STATISTICS=5 MAX_DUMP_FILE_SIZE = 1M SQL_TRACE = TRUE STATISTICS_LEVEL = ALL
Now I bounce my database to instantiate these configuration parameter changes.
| Tip | Some of these parameters can be updated online using the ALTER SYSTEM command. |
The next step is starting up my highly active concurrent database scripting (see Appendix B). These scripts use the DBMS_JOBS package to repetitively execute a slew of database changes to my Accounts schema, from multiple concurrently executed database jobs using the DBMS_JOBS package. Since I am running sessions using the DBMS_JOBS package I have to be able to find trace files for each session. So let's change the process identifier query to access multiple sessions, and find a trace file that way. So how do I find the appropriate sessions? Log into a database administrator user such as SYSTEM and execute a query something like this.
SELECT audsid, username, saddr, paddr, sid, serial# FROM v$session WHERE username = 'ACCOUNTS' AND audsid != 0;
Then I change my process identifier finding query and find a filename.
SELECT 'c:\oracle\admin\test\udump\test_ora_'||spid||'.trc' "Trace File" FROM v$process WHERE addr = ( SELECT paddr FROM V$SESSION WHERE username = 'ACCOUNTS' AND audsid != 0); Trace File --------------------------------------------------- c:\oracle\admin\test\udump\test_ora_972.trc
Trace files can look like the gibberish shown below. Not really very easy to interpret is it? Yes that is sarcastic; certainly the very lowest form of wit but apt in this case. This is where TKPROF comes into play.
====================== PARSING IN CURSOR #3 len=56 dep=1 uid=0 oct=3 lid=0 tim=13822711723 hv=4049165760 ad='67f67898' select order#,columns,types from access$ where d_obj#=:1 END OF STMT PARSE #3:c=0,e=145,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=13822711703 EXEC #3:c=0,e=136,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4, tim=13822714183 FETCH #3:c=0,e=114,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4, tim=13822714826 FETCH #3:c=0,e=78,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4, tim=13822715459 FETCH #3:c=0,e=67,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4, tim=13822716065 FETCH #3:c=0,e=64,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4, tim=13822716662 FETCH #3:c=0,e=65,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4, tim=13822717260 FETCH #3:c=0,e=42,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4, tim=13822717850 STAT #3 id=1 cnt=5 pid=0 pos=1 obj=97 op='TABLE ACCESS BY INDEX ROWID ACCESS$ ' STAT #3 id=2 cnt=5 pid=1 pos=1 obj=129 op='INDEX RANGE SCAN I_ACCESS1 '
9.3.3 TKPROF
TKPROF is essentially a text-formatting or text-parsing utility used to massage trace files into a readable format.
Syntax of TKPROF
TKPROF is available on the database server in the $ORACLE_HOME\rdbms\admin directory. To examine TKPROF utility syntax type TKPROF or TKPROF HELP=Y at the command line and hit the return key, as with many other Oracle Database utilities. TKPROF accepts an input trace file and outputs a formatted file.
Execution plans can also be generated using TKPROF from trace files for all SQL code in the trace input file. Additionally TKPROF can generate a historical record of both all recursive and nonrecursive SQL executed by a session. This is the TKPROF command syntax.
TKPROF tracefile formatted [ SORT = { option | ( option list ) } ] [ PRINT = n ] [ AGGREGATE = { YES | NO } ] [ INSERT = scriptfile ] [ SYS = { YES | NO } ] [ [ TABLE = [schema.]table ] EXPLAIN = username/ password ] [ RECORD = scriptfile ] -
SORT. Sorts by specified options, there are a multitude of them.
-
PRINT. Sorts the first n SQL statements in the trace file.
-
AGGREGATE. Groups multiple users using the same SQL text.
-
INSERT. Writes out an SQL script to generate statistics into the database.
-
TABLE. The name of the table to which query plans are written.
-
EXPLAIN. Creates SQL statement query plans.
-
RECORD. Writes out an SQL script usable to replay all nonre-cursive SQL events.
-
SYS. SYS user SQL statements and recursive SQL. A recursive SQL statement occurs when, for instance, an SQL statement requires a new extent and an extent must be created prior to completion of the SQL statement.
Using TKPROF
Now I am simply executing TKPROF on the trace file I found earlier using all useful options. On Windows a script like this could go into a batch called RTK.BAT for instance.
TKPROF c:\oracle\admin\test\udump\test_ora_%1.trc c:\tmp\%1.out INSERT = c:\tmp\%1.ins TABLE = PLAN_TABLE EXPLAIN = accounts/accounts RECORD = c:\tmp\%1.rec SYS = YES
The batch file would be executed like this.
RTK 972
This produces files called 972.OUT, 972.INS, and 972.REC. The .OUT file contains the formatted output, the .INS file contains a statistics generation script and the .REC file contains a record of nonrecursive SQL commands executed.
Interpretation of TKPROF Output
Following are sections of sample TKPROF output. Some comment is required. The first section of the TKPROF output shown is an SQL code SELECT statement contained in the trace file.
************************************************************ SELECT a.supplier_id, a.price from ( select supplier_id, min(price) as price from stocksource where stock_id = :b1 group by supplier_id order by price ) a where rownum = 1
The next section from the TKPROF output shows statistics generated by the execution of this SELECT statement expressed in three separate steps.
call count cpu elapsed disk query current rows ------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.07 0.08 0 56 0 0 Execute 10 0.02 0.01 0 0 0 0 Fetch 10 0.10 0.17 36 256 0 10 ------- ----- ----- ------- ---- ----- ------- ---- total 21 0.19 0.27 36 312 0 10
Let's examine the three separate steps.
-
Parse. Checks validity of syntax, objects and security, and generation of the query plan by the Optimizer.
-
Execute. Step for execution of SQL code. DML changes rows and SELECT builds appropriate cursors in memory.
-
Fetch. A cursor created by a SELECT statement is used to fetch the rows.
Repeating the second part of the TKPROF output for clarity let's follow it by examining the separate columns.
call count cpu elapsed disk query current rows ------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.07 0.08 0 56 0 0 Execute 10 0.02 0.01 0 0 0 0 Fetch 10 0.10 0.17 36 256 0 10 ------- ----- ----- ------- ---- ----- ------- ---- total 21 0.19 0.27 36 312 0 10
-
Count. Parse, execute, and fetch calls or executions of each type.
-
CPU. Processor time.
-
Elapsed. Total time elapsed.
-
Disk. Physical disk reads.
-
Query. Read-only query block retrievals.
-
Current. Read-write block retrievals or changes.
-
Rows. Rows processed.
The importance of the preceding TKPROF output is the ratios between the columns. What are these ratios and why are they significant?
-
Physical Disk Reads vs. Logical Reads. This is disk/(query+ current). The lower this ratio is the better, but not always. An extremely low ratio could indicate poorly tuned SQL code, an extremely high ratio could be normal depending on the application type. There is current thought in the Oracle community that logical reads in the extreme are not as efficient as once thought. Use of huge amounts of RAM and loading entire databases into the database buffer cache is often nowhere near as efficient as we are led to believe. On the contrary, LRU and MRU lists are significant because, for instance, reading a large table can push everything useful out of memory. More in Part III.
-
Block Reads vs. Rows. Block reads are often stated as being logical reads only: (query + current). I like to lump together the logical and the physical block reads: (query + current + disk) because they are all reads. The more blocks required to be read for each row the worse performance could possibly be.
-
Parse vs. Execute. We have a ratio of 1/10, which is good. If there were more parses than executions it would imply that SQL code is being re-parsed unnecessarily and the shared pool is not being shared enough, for a multitude of reasons but most likely due to poorly tuned SQL code.
The rest of the output shows a general analysis plus a query plan.
Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 88 (ACCOUNTS) (recursive depth: 1) Rows Execution Plan ---- ---------------------------------------------------- 0 SELECT STATEMENT GOAL: CHOOSE 0 COUNT (STOPKEY) 0 VIEW 0 SORT (ORDER BY STOPKEY) 0 SORT (GROUP BY) 0 TABLE ACCESS GOAL: ANALYZED (BY INDEX ROWID) OF 'STOCKSOURCE' 0 INDEX (RANGE SCAN) OF 'XFK_SS_STOCK' (NON-UNIQUE)
Personally I look at using tracing of any form and TKPROF as a very last resort. The amount of extra tuning information gained from TKPROF output is minimal if SQL code is written properly in the first place. Using TKPROF can be useful in situations where you cannot get at the SQL code, for instance in situations where all SQL code is embedded in applications code or stored procedures where an Oracle database administrator is brought in on a temporary basis, or simply because the database administrator cannot get access to SQL code or there is lack of communication with application developers. Tuning SQL code without any knowledge of the application can be very difficult. I have used TKPROF in the past to examine all trace files available on database servers and produce TKPROF EXPLAIN option generated query plans for all SQL code. I then passed recommendations onto developers for potential embedded SQL code changes. Before resorting to TKPROF I found and tuned the worst-performing SQL code statements using other tools and Oracle performance views. Example scripting for performing TKPROF EXPLAIN option query plan analysis for all SQL code executed and recorded in trace files can be found in Appendix B.
Let's go through an example showing tuning using SQL Trace and TKPROF. This is a very nasty join query from a previous chapter.
EXPLAIN PLAN SET statement_id='TEST' FOR SELECT c.name FROM customer c JOIN orders o USING(customer_id) JOIN ordersline ol USING(order_id) JOIN transactions t USING(customer_id) JOIN transactionsline tl USING(transaction_id) WHERE c.balance > 0;
This is its query plan. Note the high cost.
Query Cost Rows Bytes ---------------------------- ------- -------- --------- 1. SELECT STATEMENT on 1345027 ######## ######### 2. HASH JOIN on 1345027 ######## ######### 3. TABLE ACCESS FULL on 16 1795 44875 CUSTOMER 3. MERGE JOIN on 37726 ######## ######### 4. SORT JOIN on 18298 ######## ######### 5. MERGE JOIN on 18298 ######## ######### 6. SORT JOIN on 16864 934659 9346590 7. MERGE JOIN on 6044 934659 9346590 8. SORT JOIN on 4388 1916444 7665776 9. INDEX FAST FULL 4388 1916444 7665776 SCAN on XFK_TL_ 8. SORT JOIN on 1656 166323 997938 9. TABLE ACCESS FULL 556 166323 997938 on TRANSACTIO 6. SORT JOIN on 1434 165116 990696 7. TABLE ACCESS FULL 344 165116 990696 on ORDERS 4. SORT JOIN on 19428 1887096 7548384 5. TABLE ACCESS FULL 1518 1887096 7548384 on ORDERSLINE
Here is a tuned version of the same query.
EXPLAIN PLAN SET statement_id='TEST' FOR SELECT c.name FROM customer c WHERE c.balance > 0 AND EXISTS( SELECT o.order_id FROM orders o WHERE o.customer_id = c.customer_id AND EXISTS( SELECT order_id FROM ordersline WHERE order_id = o.order_id ) ) AND EXISTS( SELECT t.transaction_id FROM transactions t WHERE t.customer_id = c.customer_id AND EXISTS( SELECT transaction_id FROM transactionsline WHERE transaction_id = t.transaction_id ) );
Here is the query plan for the tuned version of the query. This tuned version is more than 500 times lower in cost. That is quite a difference.
Query Cost Rows Bytes ------------------------------------- ------- ----- ------ 1. SELECT STATEMENT on 2228 4 100 2. FILTER on 3. TABLE ACCESS FULL on CUSTOMER 16 4 100 3. NESTED LOOPS on 271 700 7000 4. TABLE ACCESS BY INDEX ROWID on 29 121 726 ORDER 5. INDEX RANGE SCAN on XFK_O_CUSTOMER 1 61 4. INDEX RANGE SCAN on XFK_OL_ORDERS 2 6 24 3. NESTED LOOPS on 282 711 7110 4. TABLE ACCESS BY INDEX ROWID on TRANS 28 127 762 5. INDEX RANGE SCAN on XFK_T_CUSTOMER 1 62 4. INDEX RANGE SCAN on XFK_TL_TRANSACTI 2 6 24
Now let's use SQL Trace and TKPROF to show what changed when tuning this query. Here is the query not tuned.
EXPLAIN PLAN SET statement_id='TEST' FOR SELECT c.name FROM customer c JOIN orders o USING(customer_id) JOIN ordersline ol USING(order_id) JOIN transactions t USING(customer_id) JOIN transactionsline tl USING(transaction_id) WHERE c.balance > 0 call count cpu elapsed disk query current rows --------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.52 1.20 0 818 0 0 Execute 1 0.09 0.09 0 24 0 0 Fetch 0 0.00 0.00 0 0 0 0 --------- ----- ----- ------- ---- ----- ------- ---- total 2 0.61 1.30 0 842 0 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 84 (ACCOUNTS) Rows Row Source Operation ---- ------------------------------------------- 0 HASH JOIN 0 TABLE ACCESS FULL CUSTOMER 0 MERGE JOIN 0 SORT JOIN 0 MERGE JOIN 0 SORT JOIN 0 MERGE JOIN 0 SORT JOIN 0 INDEX FAST FULL SCAN XFK_TL_TRANSACTION (object id 34989) 0 SORT JOIN 0 TABLE ACCESS FULL TRANSACTIONS 0 SORT JOIN 0 TABLE ACCESS FULL ORDERS 0 SORT JOIN 0 TABLE ACCESS FULL ORDERSLINE
Here is the tuned version of the query.
EXPLAIN PLAN SET statement_id='TEST' FOR SELECT c.name FROM customer c WHERE c.balance > 0 AND EXISTS( SELECT o.order_id FROM orders o WHERE o.customer_id = c.customer_id AND EXISTS( SELECT order_id FROM ordersline WHERE order_id = o.order_id ) ) AND EXISTS( SELECT t.transaction_id FROM transactions t WHERE t.customer_id = c.customer_id AND EXISTS( SELECT transaction_id FROM transactionsline WHERE transaction_id = t.transaction_id ) ) call count cpu elapsed disk query current rows --------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.02 0.01 0 0 0 0 Execute 1 0.03 0.02 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0 --------- ----- ----- ------- ---- ----- ------- ---- total 2 0.05 0.04 0 0 0 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 84 (ACCOUNTS) Rows Row Source Operation ---- -------------------------------------------------- 0 FILTER 0 TABLE ACCESS FULL CUSTOMER 0 NESTED LOOPS 0 TABLE ACCESS BY INDEX ROWID ORDERS 0 INDEX RANGE SCAN XFK_O_CUSTOMER (object id 32584) 0 INDEX RANGE SCAN XFK_OL_ORDERS (object id 32588) 0 NESTED LOOPS 0 TABLE ACCESS BY INDEX ROWID TRANSACTIONS 0 INDEX RANGE SCAN XFK_T_CUSTOMER (object id 32633) 0 INDEX RANGE SCAN XFK_TL_TRANSACTION (object id 34989)
All that is a lot of information. What I want to do is focus on the statistics section produced by SQL Trace and TKPROF. This is the statistics section for the query not tuned.
call count cpu elapsed disk query current rows --------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.52 1.20 0 818 0 0 Execute 1 0.09 0.09 0 24 0 0 Fetch 0 0.00 0.00 0 0 0 0 --------- ----- ----- ------- ---- ----- ------- ---- total 2 0.61 1.30 0 842 0 0
Next is the statistics section for the query tuned. Obviously we can see that both CPU usage and elapsed times have decreased substantially. Parse time is substantially decreased and execute time is decreased to a lesser degree. The different ratios are less distinct than the cost differences for the query plans. This probably implies that the query plan is not accurate, perhaps because statistics are out of date. Parse time is reduced because fewer rows are accessed and probably less SQL code library cache is being used. The execution time is decreased because fewer rows are retrieved and thus the query is reading less physical space. In short, the tuned query is a lot faster.
call count cpu elapsed disk query current rows --------- ----- ----- ------- ---- ----- ------- ---- Parse 1 0.02 0.01 0 0 0 0 Execute 1 0.03 0.02 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0 --------- ----- ----- ------- ---- ----- ------- ---- total 2 0.05 0.04 0 0 0 0
The only point to note in the case of tuning this query with SQL Trace and TKPROF is that the query was tuned in a previous chapter just by recoding the SQL statement in a more efficient manner. The extreme of utilizing SQL Trace and TKPROF was not required to tune this SQL code statement. Additionally examining this TKPROF output there is much detailed information provided but there is no information as to how to tune the SQL code.
Leaving SQL Trace on for extended periods of time can allow gathering of large amounts of analyzable trace files. However, tracing will affect performance quite drastically, so it is better switched off when not being used. Trace files can also use a lot of disk space over a period of time.
|
| < Day Day Up > |
|
EAN: 2147483647
Pages: 164