Shulou(Shulou.com)06/01 Report--

Previously simply wrote the 10046 event introduction to the article http://hbxztc.blog.51cto.com/1587495/1898624, of course, the collection of 10046 trace is not the ultimate goal, to be able to read and analyze 10046 trace and then analyze the performance problems of the corresponding sql is where 10046 trace really plays a role. But the original trace file generated by the 10046 event is used to be called a naked trace file (raw trace), and the content of the Oracle record in the naked trace file does not look so good at first glance, nor is it so easy to understand. In order to render trace files in a more intuitive and easy-to-understand way, Oracle provides the tkprof command, which is native to Oracle and can be used to translate trace files.

1. Syntax of tkprof:

Tkprof filename1 filename2 [waits=yes | no] [sort=option] [print=n] [aggregate=yes | no] [insert=filename3] [sys=yes | no] [table=schema.table] [explain=user/password] [record=filename4] [width=n]

The easiest way to use it is tkprof trace_filename output_filename

The specific usage and the meaning of the parameters refer to the official document http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94985

The output file generated by tkprof contains some trace records of sql called within Oracle. These SQL are triggered by the user's SQL. Generally speaking, it is necessary to look up some data dictionary base tables such as obj$, tab$, and so on. In general, these SQL operations consume very little resources and time. We don't need to care, what we care about is the information corresponding to the sql we are running.

2. An example of a trace corresponding to a simple sql after tkprof

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 0Execute 1 0.00 0.00 0 0Fetch 2 0.00 0.00 0 2 01-- -- total 4 0.00 0.00 0 20 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- 11 TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=38 us cost=1 size=38 card=1) 11 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 SQL ID, Plan Hash and sql text

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

2) the second part is the summary of the statistical information of each indicator when the SQL is running.

Call count cpu elapsed disk query current rows--Parse 1 0.00 0.00 00 0Execute 1 0.00 0.00 00 0Fetch 2 0.00 0.00 2 01 -total 4 0.00 0.00 0 2 0 1

Line name interpretation

Parse parses the SQL statement part

The execution part of the execute SQL statement, for the INSERT/UPDATE/DELETE statement, it is the modified row, and for the SELECT statement, it indicates the number of rows returned.

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

List interpretation

The number of times a count statement was parsed, executed, or FETCH

The total CPU time (in seconds) consumed by the cpu statement during the parsing, execution, or FETCH phase, which is 0 if the TIMED_STATISTICS is not opened

The total time (in seconds) spent by the elapsed statement in the parsing, execution, or FETCH phase, or 0 if the TIMED_STATISTICS is not opened

The total number of physical reads made by disk statements to data files on disk during parsing, execution, or FETCH phases

The number of times query statements consistently read buffer patterns during parsing, execution, or FETCH phases, usually corresponding to query statements

The number of times the current statement reads the current buffer mode during parsing, execution, or FETCH, corresponding to the INSERT/UPDATE/DELETE statement

The total number of rows produced by the rows statement, excluding the number of rows generated by the SQL subquery

3) part III Library Cache information

Lists the number of times the statement library cache miss during parsing and execution phases, and if the statement does not have a library cache miss, the tkprof is not displayed. Information such as optimizer mode is also listed.

Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYSNumber of plan statistics captured: 1

4) the fourth part is Row source plan

Rows (1st) Rows (avg) Rows (max) Row Source Operation- 11 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 times

Number of pr physical reads

Number of pw physical writes

Time consumed by time (microseconds)

The consumption of the cost operation

Size estimated return size (bytes)

Cardinality estimated by card

Part V: waiting event information for statement execution

It includes the waiting times and waiting time for each waiting 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)

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.