Introduction to Oracle 10046 event (ii)---tkprof

Before simply writing a 10046-event introduction to the article http://hbxztc.blog.51cto.com/1587495/1898624, of course, collecting 10046 trace is not the ultimate goal, able to read and analyze 10046 Trace and then analyze the performance problem of the corresponding SQL is where 10046 trace really works. However, the original trace file generated by the 10046 event is often referred to as a bare trace file (raw Trace), and the contents of an Oracle record in a bare trace file are not so apparent at first glance, and are not so easily understood. In order for the naked trace file to be presented in a more intuitive and easy-to-understand manner, Oracle provides the TKPROF command, which is brought by Oracle and can be used to translate naked trace files.

1, the TKPROF syntax:

Tkprof filename1 filename2 [Waits=yes|no] [sort=option] [print=n] [aggregate=yes|no] [Insert=filename3] [sys=yes|no] [t Able=schema.table] [Explain=user/password] [record=filename4] [width=n]

The simplest way to use it is tkprof trace_filename output_filename

Specific use method and parameter meaning reference official document http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94985

The output file generated by Tkprof contains trace records of SQL that are called by the Oracle, which are triggered by the user's SQL, which is generally used to look up some data dictionary base tables such as obj$, tab$, and so on, and these SQL runs consume very little resources and time normally. We don't need to care, we care about the various kinds of information that we run for SQL.

2, a simple SQL corresponding trace after tkprof the example

sql id: 484dcpmb3vazu plan hash: 2949544139select *from scott.emp  where empno=:xcall     count       cpu     elapsed       disk       query    current        rows------- ------   -------- ---------- ---------- ---------- ----------  ---------- parse        1      0.00        0.00          0           0          0            0Execute       1      0.00       0.00           0          0           0           0Fetch         2      0.00        0.00          0           2          0            1------- ------  -------- ---------- ------ ---- ---------- ----------  ----------total         4      0.00       0.00           0          2           0           1misses  in library cache during parse: 1Optimizer mode: ALL_ROWSParsing  user id: sysnumber of plan statistics captured: 1rows  (1st)  Rows   (avg)  Rows  (max)   row source operation---------- ---------- ---- ------  ---------------------------------------------------          1          1           1  TABLE ACCESS BY INDEX ROWID EMP  (cr=2  pr=0 pw=0 time=38 us cost=1 size=38 card=1)           1          1           1   INDEX UNIQUE SCAN PK_EMP  (cr=1 pr=0 pw=0  time=19 us cost=0 size=0 card=1) (object id 87109) 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  sql*net  message from client                      2        0.01           0.01

3. Detailed analysis of each part

1) The first part is the SQL ID, Plan hash, and SQL text

SQL Id:484dcpmb3vazu Plan hash:2949544139select *from scott.emp where empno=:x

2) The second part is a summary of the statistics of the various indicators of the SQL runtime

call     count       cpu     elapsed       disk      query     current        rows------- ------  --------  ---------- ---------- ---------- ----------  ----------parse         1      0.00        0.00          0           0          0            0Execute      1       0.00       0.00           0          0           0           0Fetch         2      0.00       0.00           0           2          0            1------- ------  -------- ---------- ---------- -- -------- ----------  ----------total        4       0.00       0.00           0          2        &Nbsp;  0           1 

Row name Explanation

• Parse Parse SQL statement section

• The execution execution portion of the Execute SQL statement, for the Insert/update/delete statement, is the modified row, and the number of rows returned for the SELECT statement

• The number of rows returned by the fetch query, only valid in the SELECT statement

Column name explanation

• Number of times the count statement was parsed, executed, or the fetch phase

• The total CPU time (in seconds) consumed by the CPU statement during the parsing, executing, or fetch phase, if Timed_statistics is not open, the value is 0

• The total time (in seconds) that the elapsed statement consumes in the parsing, executing, or fetch phase, or 0 if the timed_statistics is not open

• Disk statement The total physical read amount of the data file on disk during the parse, execute, or fetch phase

• The number of times the query statement has a consistent read pattern of buffer in the parsing, executing, or fetch phase, usually corresponding to an inquiry statement

• The number of times the current statement has been read in the buffer in the parsing, executing, or fetch phase, corresponding to the Insert/update/delete statement

• Rows generated by the rows statement, without including the number of rows produced by the SQL subquery

3) The third part of the library Cache information

Lists the number of times the library cache miss is in the parsing and executing phase of the statement, and Tkprof does not appear if the statement does not have a library cache miss. It also lists information such as optimizer mode.

Misses in library cache during Parse:1optimizer mode:all_rowsparsing user id:sysnumber of plan statistics captured:1

4) The fourth part is the row source plan

rows  (1st)  Rows  (avg)  Rows  (max)   row  source operation---------- ---------- ----------  ----------------------------- ----------------------         1           1          1  table  ACCESS BY INDEX ROWID EMP  (cr=2 pr=0 pw=0 time=38 us  cost=1 size=38 card=1)          1           1          1    INDEX UNIQUE SCAN PK_EMP  (cr=1 pr=0 pw=0 time=19 us  cost=0 size=0 card=1) (object id 87109) 

• CR Consistent Read frequency

• PR Physical Read times

• PW Physical Write times

• Time consumed (in microseconds)

• Cost of this operation

• Size Estimated return sizes (bytes)

• Cardinality of card estimation

Part V: Wait event information for statement execution

Includes the number of waits and wait times for each wait event.

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  SQL*Net message from client                      2         0.01          0.01 

Official Document: http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF01010

Reference Document: Https://blogs.oracle.com/askmaclean/entry/maclean%E6%95%99%E4%BD%A0%E8%AF%BBoracle_10046_sql_trace

MOS Document: TKProf Interpretation (9i and above) (document ID 760786.1)

Interpreting Raw sql_trace Output (document ID 39817.1)

This article is from the "DBA fighting!" blog, so be sure to keep this source http://hbxztc.blog.51cto.com/1587495/1898753

Introduction to Oracle 10046 event (ii)---tkprof