Oracle tool: tkprof

 

 

1 Definition

An executable tool used to analyze Oracle tracking files and generate clearer and more reasonable output results as needed

 

2 preferences

F:\>tkprofUsage: 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    execnt  number of execute was called    execpu  cpu time spent executing    exeela  elapsed time executing    exedsk  number of disk reads during execute    exeqry  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 during fetch    fchcu   number of buffers for current read during fetch    fchrow  number of rows fetched    userid  userid of user that parsed the cursor

Note:
① Fchela this is a useful sort option. In the generated. PRF file, the SQL statements that consume the most time are displayed at the beginning.
② Sys = No SQL statements executed as sys are not displayed, increasing readability

 

3. Definitions of columns in the tkprof output file

call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------

Note:
(I) Call:
Each SQL statement is divided into three parts.
① Parse: converts SQL statements into execution plans, including checking permissions, tables, and their associated objects.
② Execute: executed by the SQL engine. The transaction types vary.
③ Fetch: In this step, only select statements are executed, and buffer cache is the main battlefield.
(Ii) count:
Number of times this SQL statement is parse, execute, and fetch
(Iii) CPU: the CPU time consumed by the SQL statement (unit: S)
(Iv) 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:
In the consistent read mode, the number of buffers obtained by each stage. In consistency mode, buffer is used to provide consistency for a long query.
Read Snapshot
(Vii) current:
The number of buffers in each stage in the current read mode.
Donerows:
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 DML statements, the returned result is in the execute step.

 

4 steps for using tkprof

(1) set timed_statistic = true at the instance level
SQL> show parameter timed_statistic

Name_col_plus_show_p type value_col_plus_show _
--------------------------------------------------------------
Timed_statistics Boolean true
(2) use various tools to obtain the TRC file for viewing the session
(3) locate the generated TRC file in the udump path.
(4) tkprof analysis on the TRC File
Tkprof tracefile OUTFILE [Options]
Note: This statement does not end with a semicolon !!

 

5 cases

18:32:55 HR @ orcl (^ ω ^) alter session set events '10046 trace name context forever, level 12'; the session has been changed. 18:34:00 HR @ orcl (^ ω ^) Select count (*) from t; count (*) ---------- 2:34:00 HR @ orcl (^ ω ^) update T1 set tname = 'think high' where id = 1; 1 row updated. 18:34:30 HR @ orcl (^ ω ^) alter session set events '10046 trace name context off'; the session has been changed. 18:34:55 HR @ orcl (^ ω ^) exitd: \ oracle \ product \ 10.2.0 \ admin \ orcl \ udump> tkprof orcl_ora_6004.trc C: \ Users \ Administrator \ tkprof_starting.txt sys = No waits = Yes sort = fchetkprof: 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:

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse       11      0.03       0.16          0          0          0           0Execute     41      0.07       0.22          0          0          0           0Fetch       48      0.03       0.12          3        118          0          50------- ------  -------- ---------- ---------- ---------- ----------  ----------total      100      0.14       0.51          3        118          0          50Misses in library cache during parse: 11Misses in library cache during execute: 11Elapsed times include waiting 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.trcTrace file compatibility: 10.01.00Sort 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.

Note:
① This session contains 44 SQL statements and 41 recursive statements.
② Calculate hit ratio
Logical reads = consistent gets + db block gets
Consistent gets = execute of the query column + fetch of the query Column
Db block gets = execute + fetch of the current column
Therefore, logical reads = 118 + 0 + 0 = 118
Physical reads = disk column, that is, 3
Therefore, hit ratio = L/(L + p) = 97.5%
③ There is also a very important parameter. The number of fetch times and the number of rows of the obtained records. In general, we use as few fetch as possible to obtain as many records as possible.
That is, the fetch value is much smaller than the number of records obtained. As shown in the preceding example, fetch takes 48 and rows 50, which indicates
Some records are obtained through fetch several times. Some SQL statements of this session need to be optimized.
④ The parse of the query column shows the data read from the row cache.

 

The two SQL statements in the tkprof file are extracted as follows:

********************************************************************************select count(*) from tcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.01       0.06          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.01          6          7          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.01       0.08          6          7          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing 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)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          0.00

Note:
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 fetch line.

********************************************************************************update t1 set tname='think high' where id=1call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.03          0          5          2           1Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        2      0.00       0.03          0          1          1           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing 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)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

Note:
This statement accesses five blocks to find the required update records. During update execution, only two records are accessed, and a total of one record is updated.

DML statements mainly look at the execute line.