Oracle tool: tkprof Analysis

Oracle tool: tkprof Analysis 1 Definition of the executable tool used to analyze the oracle trace file and generate a clearer and more reasonable output result as needed 2 preference [SQL] F: \> tkprof www.2cto.com Usage: tkprof tracefile outputfile [explain =] [table =] [print =] [insert =] [sys =] [sort =] table = schema. tablename Use 'schema. tablename 'with 'explain = 'option. explain = user/password Connect to ORACLE and issue explain plan. print = integer List only the first 'integer' SQL statements. aggregate = yes | No insert = filename List SQL statements and data inside INSERT statements. sys = no TKPROF does not list SQL statements run as user SYS. record = filename Record non-recursive statements found in the trace file. waits = yes | no Record summary for any wait events found in the trace file. sort = option Set of zero or more of the following sort options: prscnt number of times parse was called prscpu cpu time Parsing prsela elapsed time parsing prsdsk number of disk reads during parse prsqry number of buffers for consistent read during parse prscu number of buffers for current read during parse prsmis number of misses in library cache during parse number of execute was called execpu cpu time spent executing www.2cto.com exeela elapsed time executing exedsk number of disk reads during execute exe Qry number of buffers for consistent read during execute execu number of buffers for current read during execute exerow number of rows processed during execute exemis number of library cache misses during execute fchcnt number of times fetch was called fchcpu cpu time spent fetching fchela elapsed time fetching fchdsk number of disk reads during fetch fchqry number of buffers for consistent read d Uring fetch fchcu number of buffers for current read during fetch fchrow number of rows fetched userid of user that parsed the cursor Note: ① fchela is a useful sort option, which is generated. in the prf file, the SQL statements that consume the most time are placed at the beginning. ② sys = no the SQL statements executed as sys are not displayed, increase readability 3 Definitions of columns in the tkprof output file [SQL] call count cpu elapsed disk query current rows ------- ------ -------- ---------- Note: www.2cto.com (I) c All: Each SQL statement is divided into three parts: ① parse: converts the SQL statement into an execution plan, including checking the permission, whether the table and its associated objects exist. ② execute: executed by the SQL engine, (3) fetch: only select statements are executed in this step. buffer cache is the main battlefield. (2) count: number of times this SQL statement is executed by parse, execute, and fetch. (3) cpu: cpu time consumed by the SQL statement (unit: s) (4) elapsed: the execution time of the SQL statement in each stage (v) disk: number of physical blocks read from data files on the disk (vi) query: Number of buffers obtained by each stage in consistent read mode. In consistency mode, buffer is used to provide consistent read snapshot for a long query. (vii) current: the number of buffers obtained in each phase in the current read mode. Rows: the number of records returned by all SQL statements, but does not include records returned by subqueries. For the select statement, the return value is in the fetch step for the DML statement, the returned result is the use of the tkprof in the execute step www.2cto.com 4 (1) set timed_statistic = true SQL> show parameter timed_statistic unsupported TYPE 1_1_1_timed_statistics boolean TRUE (2) obtained using a variety of tools. to view the trc file of the session (3) locate the generated trc file in the udump path (4) perform tkprof analysis on the trc file tkprof tracefile outfile [options] Note: this statement does not end with a semicolon !! 5 case [SQL] 18:32:55 hr @ ORCL (^ ω ^) alter session set events '10046 trace name context forever, level 12'; session changed. 18:34:00 hr @ ORCL (^ ω ^) select count (*) from t; COUNT (*) ---------- 2 18:34:00 hr @ ORCL (^ ω ^) update t1 set tname = 'think high' where id = 1; www.2cto.com has updated 1 line. 18:34:30 hr @ ORCL (^ ω ^) alter session set events '10046 trace name context off'; the session has been changed. 18:34:55 hr @ ORCL (^ ω ^) exit D: \ oracle \ product \ 10.2.0 \ admin \ orcl \ udump> tkprof orcl_ora_6004.trc C: \ Users \ Administrator \ tkprof_starting.txt sys = no waits = yes sort = fche TKPROF: Release 10.2.0.1.0-Production on Sunday September 23 19:19:13 2012 Copyright (c) 1982,200 5, Oracle. all rights reserved. the last part of this tkprof file is as follows: [SQL] OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS www.2cto.com call count cpu elapsed disk que Ry current rows ------- ------ -------- ---------- Parse 11 0.03 0.16 0.07 0 0 0 0 0 Execute 41 0.22 0.03 0 0 0 0 Fetch 48 0.12 118 3 50 ----------------------------------------- ---------- total 100 0.14 0.51 3 118 0 50 Misses in library cache during parse: 11 Misses in library cache during execute: 11 Elapsed times include wai Ting on following events: Event waited on Times Max. wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 3 0.02 0.05 3 user SQL statements in session. 41 internal SQL statements in session. 44 SQL statements in session. **************************************** **************************************** trace file: orcl_ora_6004.trc Trace f Ile compatibility: 10.01.00 Sort options: fchela 1 session in tracefile. 3 user SQL statements in trace file. 41 internal SQL statements in trace file. 44 SQL statements in trace file. 14 unique SQL statements in trace file. 902 lines in trace file. 55 elapsed seconds in trace file. www.2cto.com Note: ① there are 44 SQL statements in this session, and 41 recursive statements are analyzed. ② calculate hit ratio logical reads = consistent gets + db block gets Consistent gets = execute of the query column + fetch db block of the query column gets = execute of the current column + fetch of the current column. Therefore, logical reads = 118 + 0 + 0 + 0 = 118 physical reads = disk column, that is, 3. Therefore, hit ratio = L/(L + P) = 97.5% ③ another parameter is very important. The number of fetch times and the number of rows in the obtained records are generally used to obtain as many records as possible with as few fetch as possible, that is, the fetch value is much smaller than the number of records obtained. The above example shows that fetch is 48 and rows 50, which indicates that some records are obtained through fetch several times. Some SQL statements of this session need to be optimized. ④ From the parse of the query column, we can see that two SQL statements in the tkprof file read from the row cache are extracted as follows: [SQL] *********************************** **************************************** * ** select count (*) from t www.2cto.com call count cpu elapsed disk query current rows ------- ------ -------- ---------- Parse 1 0.01 0.06 0 0 0 0 Execute 1 0.00 0 0 0 Fetch 2 0.00 6 7 0 1 ----------- -- -------- ---------- Total 4 0.01 0.08 6 7 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 55 Rows Row Source Operation ------- --------------------------------------------------- 1 sort aggregate (cr = 7 pr = 6 pw = 0 time = 15493 us) 2 table access full t (cr = 7 pr = 6 pw = 0 time = 15449 us) www.2cto.com Elapsed times include Waiting on following events: Event waited on Times Max. wait Total Waited ------------------------------------------ Waited -------------- SQL * Net message to client 2 0.00 0.00 db file sequential read 1 0.01 0.01 db file scattered read 1 0.00 0.00 SQL * Net message from client 2 0.00 comments: from the above output, we can see that this statement accesses seven blocks to find the record to be selected and returns one record. This query parse is one time and hard parse is one time. Select statements mainly refer to the [SQL] ********************************* line of fetch. **************************************** * ******** update t1 set tname = 'think high' where www.2cto.com id = 1 call count cpu elapsed disk query current rows ----------------------------------------------------------------------- parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.03 0 5 2 1 Fetch 0 0.00 0 0 0 0 ------- ------ -------- ---------- total 2 0.00 0.00 0 1 1 1 misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 55 Rows Row Source Operation ------- ------------------------------------------------- 1 UPDATE T1 (cr = 1 pr = 0 pw = 0 time = 31186 us) 1 index unique scan INDEX_T1 (cr = 1 pr = 0 pw = 0 time = 23 us) (object id 54498) www.2cto.com 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 0.00 0.00 notes: this statement accesses five blocks to find the required update records. During update execution, only two records are accessed. A total of one record is updated. DML statements mainly refer to the execute line.