TKPROF工具使用说明及其输出的简单解释

--TKPROF工具使用说明及其输出的简单解释

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]

--不加参数输出tkprof会出现简单的说明。
[oracle@ocm1 tmp]$ tkprof
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
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

--简单演示使用tkprof
EODA@PROD1> exec dbms_session.session_trace_enable;

PL/SQL procedure successfully completed.

EODA@PROD1> select count(*) from big_table;

COUNT(*)
----------
10000000

EODA@PROD1> exec dbms_session.session_trace_disable;

PL/SQL procedure successfully completed.

EODA@PROD1> select value from v$diag_info where name='Default Trace File';

VALUE
----------------------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/prod1/PROD1/trace/PROD1_ora_7923.trc

[oracle@ocm1 tmp]$ tkprof /u01/app/oracle/diag/rdbms/prod1/PROD1/trace/PROD1_ora_7923.trc 7923.txt sys=no sort=prsela,exeela,fchela

TKPROF: Release 11.2.0.3.0 - Development on Mon Feb 27 19:09:16 2017

Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

--解释TKPROF输出
[oracle@ocm1 tmp]$ cat 7923.txt

以下为头部信息，包含跟踪文件名，生成输出的sort参数等信息。
TKPROF: Release 11.2.0.3.0 - Development on Mon Feb 27 19:09:16 2017

Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.

Trace file: /u01/app/oracle/diag/rdbms/prod1/PROD1/trace/PROD1_ora_7923.trc
Sort options: prsela exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

以下开始为每条SQL语句的信息。
SQL ID: 6fxg0qj7j7ftd Plan Hash: 1764098166

select count(*)
from
big_table

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1.92 2.20 22167 22188 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.92 2.20 22167 22188 0 1

--count：数据库调用执行的次数。
--cpu：花费在数据库调用上CPU时间的总和，单位秒。
--elapsed：花费在数据库调用上的运行时间综合，单位秒。如果值高于cpu则会在统计后部分找到等待事件信息。
--disk：代表物理读的块数。如果这值比逻辑读大（disk>query+current）则代表块涌入了临时表空间。
--query：一致性逻辑读的块数。通常查询会用到这种逻辑读。
--current：在当前模式下使用逻辑读读取的块数。通常INSERT/UPDATE/MERGE/DELETE会产生此类。
--rows：处理的行数。对于查询来说是获取的行数，对于修改语句来说是影响的行数。

Misses in library cache during parse: 1
--代表在解析期间的硬解析数。

Optimizer mode: ALL_ROWS
--优化器模式。

Parsing user id: 97
--解析次SQL语句的用户ID。

Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=22188 pr=22167 pw=0 time=2200607 us)
10000000 10000000 10000000 INDEX FAST FULL SCAN BIG_TABLE_PK (cr=22188 pr=22167 pw=0 time=4917338 us cost=6256 size=0 card=9980600)(object id 85100)
--cr是一致性逻辑读的块数。
--pr是物理读的块数。
--pw是物理写的块数。
--time是执行操作运行时间总和，单位微秒。
--cost是操作的估计成本。
--size是操作返回的预计数据大小（byte）。
--card是操作返回的预估行数。

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
Disk file operations I/O 1 0.00 0.00
db file sequential read 63 0.01 0.02
db file scattered read 204 0.04 1.03
SQL*Net message from client 2 0.00 0.00
********************************************************************************

--等待时间的统计，包括发生次数，发生最大时间，发生总时间。

SQL ID: 9arnynjk2xh7g Plan Hash: 0

BEGIN dbms_session.session_trace_enable; END;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.02 1 74 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.02 1 74 0 1

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 97

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
********************************************************************************

SQL ID: 9babjv8yq8ru3 Plan Hash: 0

BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.01 0 33 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 0 33 0 2

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 97

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 12.46 22.37
********************************************************************************

SQL ID: 4pzfk82288xrc Plan Hash: 0

BEGIN dbms_session.session_trace_disable; END;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
-------
4000
------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 97

********************************************************************************
--在所有SQL语句的报告后，可以看到执行统计信息，解析和等待事件的综合统计。
--这里需要注意的就是非递归SQL从递归SQL里分离出来。
--Recursive SQL是指sys用户执行的语句，非业务SQL，在TKPROF可以显示Recursive SQL，也可以过滤掉，过滤掉的方法就是，TKPROF后加参数sys=no。

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 5 0.00 0.03 1 107 0 4
Fetch 2 1.92 2.20 22167 22188 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 1.94 2.24 22168 22295 0 5

Misses in library cache during parse: 3
Misses in library cache during execute: 2

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 12.46 22.37
db file sequential read 63 0.01 0.02
Disk file operations I/O 1 0.00 0.00
db file scattered read 204 0.04 1.03

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.00 0.00 0 0 0 0
Execute 31 0.00 0.05 0 0 0 0
Fetch 68 0.00 0.05 3 118 0 44
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 109 0.01 0.10 3 118 0 44

Misses in library cache during parse: 6
Misses in library cache during execute: 6

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 3 0.04 0.05

--对当前会话的SQL数量进行概括。
5 user SQL statements in session.
21 internal SQL statements in session.
26 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/prod1/PROD1/trace/PROD1_ora_7923.trc
Trace file compatibility: 11.1.0.7
Sort options: prsela exeela fchela
1 session in tracefile.
5 user SQL statements in trace file.
21 internal SQL statements in trace file.
26 SQL statements in trace file.
21 unique SQL statements in trace file.
593 lines in trace file.
24 elapsed seconds in trace file.