细说tkprof的使用方法

熟悉oracle的同学，对tkprof应该不会陌生。今天用到tkprof，有些语法变得模糊起来。查看文档，重新梳理有关tkprof的有关知识，加深记忆。 通过tkfprof可以非常方便的跟踪诊断sql语句的执行效率。结合explain plan的使用，更是如虎添翼。 sql trace为我们查看

熟悉oracle的同学，对tkprof应该不会陌生。今天用到tkprof，有些语法变得模糊起来。查看文档，重新梳理有关tkprof的有关知识，加深记忆。

通过tkfprof可以非常方便的跟踪诊断sql语句的执行效率。结合explain plan的使用，更是如虎添翼。

sql trace为我们查看某天sql 语句的性能信息提供了可能，通常sqltrace可以生成下面的统计信息：

Parse, execute, and fetch counts 解析 执行和抓取的动作数量CPU and elapsed times 花费在cpu和整个操作上的时间Physical reads and logical reads 物理读和逻辑读Number of rows processed 处理的记录数量Misses on the library cache 库缓存的丢失率Username under which each parse occurred 执行用户Each commit and rollback 每次的提交和回滚操作 （tkprofl不会处理这些信息）Wait event data for each SQL statement, and a summary for each trace file 针对每条sql语句和所有的sql语句生成事件信息数据除此之外，如果在sql trace期间，跟踪的语句游标已经关闭，sql trace还会提供如下的行源信息 Row operations showing the actual execution plan of each SQL statementNumber of rows, number of consistent reads, number of physical reads, number of physical writes, and time elapsed for each operation on a row 语法格式：

[oracle@oadata trace]$ tkprofUsage: tkprof tracefile outputfile [explain= ] [table= ]              [print= ] [insert= ] [sys= ] [sort= ]  table=schema.tablename   Use 'schema.tablename' with 'explain=' option. --手动生成explain plan时，存储中间信息的临时表，默认为PROF$PLAN_TABLE  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN. --手动生成explain时，连接数据库的用户名和密码   print=integer    List only the first 'integer' SQL statements.--仅仅处理前integer数量的sql语句，如果我们需要生成脚本，该参数对脚本中包含的sql数量是不影响的  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. --是否包含sys用户生成的信息，如递归sql  record=filename  Record non-recursive statements found in the trace file. --生成脚本，脚本包含跟踪文件中的非递归sql语句  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<strong style="color:transparent">本文来源gao@daima#com搞(%代@#码网@</strong> 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

sql trace与执行计划： 如果在sqltrace期间，sql语句的游标已经关闭，sqltrace中会包含执行计划的相关信息

SQL> show userUSER 为 "SCOTT"SQL> explain plan for select object_id,object_name,object_type from tab1 where object_id = 1000;已解释。SQL> select * from table(dbms_xplan.display());PLAN_TABLE_OUTPUT----------------------------------------------------------------------------------------------------Plan hash value: 2086140937------------------------------------------------------------------------------------| Id  | Operation		    | Name | Rows  | Bytes | Cost (%CPU)| Time	   |------------------------------------------------------------------------------------|   0 | SELECT STATEMENT	    |	   |	 1 |	41 |	 1   (0)| 00:00:01 ||   1 |  TABLE ACCESS BY INDEX ROWID| TAB1 |	 1 |	41 |	 1   (0)| 00:00:01 ||*  2 |   INDEX RANGE SCAN	    | IND1 |	 1 |	   |	 1   (0)| 00:00:01 |------------------------------------------------------------------------------------Predicate Information (identified by operation id):PLAN_TABLE_OUTPUT-------------------------------------------------------------------------------------------------------------------------------------------------------   2 - access("OBJECT_ID"=1000)Note-----   - dynamic sampling used for this statement (level=2)已选择18行。SQL> alter session set sql_trace=true;会话已更改。SQL> alter session set tracefile_identifier='test1';会话已更改。SQL> select object_id,object_name,object_type from tab1 where object_id = 1000;未选定行

跟踪文件：

********************************************************************************SQL ID: 25kr54b04dq4v Plan Hash: 2086140937select object_id,object_name,object_type from tab1 where object_id = 1000call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          2          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          0          2          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.00          0          4          0           0Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  Number of plan statistics captured: 1--Rows (1st) Rows (avg) Rows (max)  Row Source Operation------------ ---------- ----------  -----------------------------------------------------         0          0          0  TABLE ACCESS BY INDEX ROWID TAB1 (cr=2 pr=0 pw=0 time=20 us cost=1 size=41 card=1)--         0          0          0   INDEX RANGE SCAN IND1 (cr=2 pr=0 pw=0 time=16 us cost=1 size=0 card=1)(object id 101626)********************************************************************************

如果游标没有关闭，则跟踪文件中不会包含该游标的执行计划信息。

SQL> Declare--Cursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 1111;Object_Id Number;Object_Name Varchar2(30);Object_Type Varchar2(19);BeginOpen  C;Fetch C Into Object_Id,Object_Name,Object_Type;Dbms_Lock.Sleep(1000);Close C; 11  End;

********************************************************************************SQL ID: dxz49cn75rxtz Plan Hash: 2086140937SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE FROM TAB1 WHERE OBJECT_ID = 1111call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          2          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          0          3          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.00          0          5          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83     (recursive depth: 1)********************************************************************************

如果之前sql语句已经执行过，则会包含执行计划

Declare--Cursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 1000;Object_Id Number;Object_Name Varchar2(30);Object_Type Varchar2(19);BeginOpen  C;Fetch C Into Object_Id,Object_Name,Object_Type;Dbms_Lock.Sleep(1000);Close C; 11  End; 12  /

********************************************************************************SQL ID: 9guk3zj6busz4 Plan Hash: 2086140937SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE FROM TAB1 WHERE OBJECT_ID = 1000call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          2          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          0          2          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.00          0          4          0           0Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83     (recursive depth: 1)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         0          0          0  TABLE ACCESS BY INDEX ROWID TAB1 (cr=2 pr=0 pw=0 time=19 us cost=1 size=41 card=1)         0          0          0   INDEX RANGE SCAN IND1 (cr=2 pr=0 pw=0 time=16 us cost=1 size=0 card=1)(object id 101626)********************************************************************************

如果在跟踪文件中，不存在执行计划的相关信息，是否有其他的方法来生成执行计划那？当然有，利用explain参数选项就可以达到这个目的，测试tkprof会议explain指定的用户登录数据库，执行explain plan相关的语句来生成执行计划，并写入到跟踪文件：

SQL> DeclareCursor C Is Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000;Object_Id Number;Object_Name Varchar2(30);Object_Type Varchar2(19);BeginOpen  C;Fetch C Into Object_Id,Object_Name,Object_Type;Dbms_Lock.Sleep(1000);Close C; 11  End; 12  /

********************************************************************************SQL ID: 9k9wj84nxpm6t Plan Hash: 2086140937SELECT OBJECT_ID,OBJECT_NAME,OBJECT_TYPE FROM TAB1 WHERE OBJECT_ID = 2000call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          2          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          0          3          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.00          0          5          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)   (recursive depth: 1)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      0   TABLE ACCESS (BY INDEX ROWID) OF 'TAB1' (TABLE)      0    INDEX   MODE: ANALYZED (RANGE SCAN) OF 'IND1' (INDEX)********************************************************************************

tkprof会累计相同的sql语句信息，并在文件的最后累计所有语句的相关信息：

SQL> Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000; OBJECT_ID OBJECT_NAME			  OBJECT_TYPE---------- ------------------------------ -------------------      2000 V_$SQLSTATS_PLAN_HASH	  VIEWSQL> Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000; OBJECT_ID OBJECT_NAME			  OBJECT_TYPE---------- ------------------------------ -------------------      2000 V_$SQLSTATS_PLAN_HASH	  VIEW

跟踪文件内容：

PARSING IN CURSOR #47244034021040 len=73 dep=0 uid=83 oct=3 lid=83 tim=1388022158115297 hv=2221247730 ad='c9810e20' sqlid='88tvucq26b37k'Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000END OF STMTPARSE #47244034021040:c=3999,e=4256,p=0,cr=73,cu=0,mis=1,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115296EXEC #47244034021040:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115394FETCH #47244034021040:c=0,e=41,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2086140937,tim=1388022158115541FETCH #47244034021040:c=0,e=11,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022158115877STAT #47244034021040 id=1 cnt=1 pid=0 pos=1 obj=101625 op='TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=34 us cost=2 size=41 card=1)'STAT #47244034021040 id=2 cnt=1 pid=1 pos=1 obj=101626 op='INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=28 us cost=1 size=0 card=1)'*** 2013-12-26 09:42:39.915CLOSE #47244034021040:c=0,e=16,dep=0,type=0,tim=1388022159915788=====================PARSING IN CURSOR #47244034021040 len=73 dep=0 uid=83 oct=3 lid=83 tim=1388022159916048 hv=2221247730 ad='c9810e20' sqlid='88tvucq26b37k'Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000END OF STMTPARSE #47244034021040:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916046EXEC #47244034021040:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916171FETCH #47244034021040:c=0,e=65,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2086140937,tim=1388022159916330FETCH #47244034021040:c=0,e=139,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=2086140937,tim=1388022159916721STAT #47244034021040 id=1 cnt=1 pid=0 pos=1 obj=101625 op='TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=65 us cost=2 size=41 card=1)'STAT #47244034021040 id=2 cnt=1 pid=1 pos=1 obj=101626 op='INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=186 us cost=1 size=0 card=1)'

tkprof格式化跟踪文件后的内容：

SQL ID: 88tvucq26b37k Plan Hash: 2086140937Select Object_Id,Object_Name,Object_Type From Tab1 Where Object_Id = 2000call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        2      0.00       0.00          0         73          0           0Execute      2      0.00       0.00          0          0          0           0Fetch        4      0.00       0.00          0          8          0           2------- ------  -------- ---------- ---------- ---------- ----------  ----------total        8      0.00       0.00          0         81          0           2Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 2Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  TABLE ACCESS BY INDEX ROWID TAB1 (cr=4 pr=0 pw=0 time=50 us cost=2 size=41 card=1)         1          1          1   INDEX RANGE SCAN IND1 (cr=3 pr=0 pw=0 time=107 us cost=1 size=0 card=1)(object id 101626)

insert和records使用示例： sqlplus中执行的脚本

SQL> select user from dual;USER------------------------------SCOTTSQL> select object_id ,object_name from tab1 where object_id  select count(*) from tab1;  COUNT(*)----------     73124

tkprof处理跟踪文件：

[oracle@oadata trace]$ tkprof *_test1.trc test1.txt insert=insert.sql record=record.sqlTKPROF: Release 11.2.0.3.0 - Development on 星期四 12月 26 10:10:06 2013Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.[oracle@oadata trace]$ cat insert.sqlREM  Edit and/or remove the following  CREATE TABLEREM  statement as your needs dictate.CREATE TABLE  tkprof_table( date_of_insert                       DATE   ,cursor_num                           NUMBER ,depth                                NUMBER ,user_id                              NUMBER ,parse_cnt                            NUMBER ,parse_cpu                            NUMBER ,parse_elap                           NUMBER ,parse_disk                           NUMBER ,parse_query                          NUMBER ,parse_current                        NUMBER ,parse_miss                           NUMBER ,exe_count                            NUMBER ,exe_cpu                              NUMBER ,exe_elap                             NUMBER ,exe_disk                             NUMBER ,exe_query                            NUMBER ,exe_current                          NUMBER ,exe_miss                             NUMBER ,exe_rows                             NUMBER ,fetch_count                          NUMBER ,fetch_cpu                            NUMBER ,fetch_elap                           NUMBER ,fetch_disk                           NUMBER ,fetch_query                          NUMBER ,fetch_current                        NUMBER ,fetch_rows                           NUMBER ,ticks                                NUMBER ,sql_statement                        LONG );set sqlterminator offINSERT INTO tkprof_table VALUES(  SYSDATE, 1, 0, 83, 1, 1000, 1321, 0, 0, 0, 1 , 1, 0, 40, 140733193388032, 0, 206158430208, 140733193388032, 140733193388032 , 2, 0, 20, 0, 0, 0, 1, 625 , 'select user from dual')/INSERT INTO tkprof_table VALUES(  SYSDATE, 2, 1, 83, 1, 0, 658, 0, 0, 0, 1 , 1, 2000, 1288, 140733193388032, 0, 0, 1, 0 , 1, 1000, 1824, 0, 69, 0, 1, 18354695 , 'SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param(''parallel_execution_enabled'', ''false'') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("TAB1") FULL("TAB1") NO_PARALLEL_INDEX("TAB1") */ :"SYS_B_2" AS C1, CASE WHEN "TAB1"."OBJECT_ID"<:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "SCOTT"."TAB1" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "TAB1") SAMPLESUB')/INSERT INTO tkprof_table VALUES(  SYSDATE, 2, 1, 83, 1, 0, 624, 0, 0, 0, 1 , 1, 2000, 1436, 140733193388032, 0, 0, 1, 0 , 1, 0, 73, 0, 2, 0, 1, 2487 , 'SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param(''parallel_execution_enabled'', ''false'') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("TAB1") INDEX("TAB1" IND1) NO_PARALLEL_INDEX("TAB1") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3  FROM "SCOTT"."TAB1" "TAB1" WHERE "TAB1"."OBJECT_ID"<:"SYS_B_6" AND ROWNUM <= :"SYS_B_7") SAMPLESUB')/INSERT INTO tkprof_table VALUES(  SYSDATE, 1, 0, 83, 1, 3998, 2275, 0, 2, 0, 1 , 1, 0, 25, 140733193388032, 0, 0, 0, 0 , 3, 0, 83, 0, 7, 0, 18, 1697 , 'select object_id ,object_name from tab1 where object_id < 20')/INSERT INTO tkprof_table VALUES(  SYSDATE, 2, 1, 83, 1, 1000, 614, 0, 0, 0, 1 , 1, 1000, 1204, 140733193388032, 0, 0, 1, 0 , 1, 1000, 1447, 0, 69, 0, 1, 8979687 , 'SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param(''parallel_execution_enabled'', ''false'') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("TAB1") FULL("TAB1") NO_PARALLEL_INDEX("TAB1") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "SCOTT"."TAB1" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5") SEED (:"SYS_B_6") "TAB1") SAMPLESUB')/INSERT INTO tkprof_table VALUES(  SYSDATE, 1, 0, 83, 1, 2000, 1703, 0, 2, 0, 1 , 1, 0, 35, 140733193388032, 0, 0, 0, 0 , 2, 12998, 12565, 159, 169, 0, 1, 13861 , 'select count(*) from tab1')/set sqlterminator on[oracle@oadata trace]$ cat record.sqlselect user from dual ;select object_id ,object_name from tab1 where object_id < 20 ;select count(*) from tab1 ;[oracle@oadata trace]$ 

使用tkprof和sql trace需要知识和经验的结合，现摘录官方文档中的部分内容，对你我或许有一定的启示作用：

Avoiding the Argument Trap

喜欢 (0)赏

[搞代码]

分享 (0)