使用TKPROF格式化TRACE输出之“解剖麻雀”

1、【TKPROF】使用TKPROF格式化TRACE输出之“解剖麻雀” 2009-10-21 11:26:54 【SQL_TRACE】SQL优化及性能诊断好帮手1.与之上次使用到的SQL_TRACE功能相比，我们这次将使用更高级的trace命令（10046）来做演示。我们先启用“高级”的10046事件生成一份待格式化的trace文件1）连接到普通用户secsysora10g> conn sec/secConnected.2）先将timed_statistics参数设置为true，这样可以使TKPROF工具能提供更多的有意义的信息，方便性能诊断secora10g> alter sessi

2、on set timed_statistics=true;Session altered.3）“高级”之所在，我们这里启用10046的level 12对当前会话进行跟踪。（1）在此，给出10046各level的解释参考：level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)等同于标准的SQL_TRACE=TRUE；level 4 to enable SQL_TRACE and also capture bind variable values in the trace file启用SQL_TRACE，

3、并捕捉跟踪文件中的绑定变量；level 8 to enable SQL_TRACE and also capture wait events into the trace file启用SQL_TRACE，并捕捉跟踪文件中的等待事件；level 12 to enable standard SQL_TRACE and also capture bind variables and wait events启用SQL_TRACE，并捕捉跟踪文件中的绑定变量和等待事件（捕获信息能力最强）。（2）对当前会话启用level 12的跟踪：secora10g> alter session set even

4、ts '10046 trace name context forever, level 12'Session altered.（3）【补充】如果想使用这种高级方法对其他的会话进行跟踪的话，可以使用如下的SQL语句开启和关闭：开启：execute dbms_system.set_ev(sid,serial#,10046,12,'');关闭：execute dbms_system.set_ev(sid,serial#,10046,0,'');举例如下：A.获得sid, serial#的信息sysora10g> select sid, seria

5、l# from v$session;B.开启sysora10g> execute dbms_system.set_ev(543,1306,10046,12,'');C.关闭sysora10g> execute dbms_system.set_ev(543,1306,10046,0,'');4）在该会话中运行一条具体的SQL语句，此处使用到的实验表t中包含1亿条数据。该SQL语句的执行情况将被细致的记录到trace文件中。secora10g> select count(*) from t;  COUNT(*)- 1000000

6、005）关闭当前会话的跟踪secora10g> alter session set events '10046 trace name context off'Session altered.2.在udump目录中找到刚刚生成的trace文件（关于如何快速获得生成的trace文件的方法有很多种，选择一个适合自己的就OK），并使用TKPROF对其进行格式化，然后打印一下全部输出，后面将对每一个输出项做一下“解剖麻雀”:)ora10gsecDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc

7、ora10g_ora_21213.prfTKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009Copyright (c) 1982, 2005, Oracle.  All rights reserved.ora10gsecDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prfTKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009Copyright (

8、c) 1982, 2005, Oracle.  All rights reserved.Trace file: ora10g_ora_21213.trcSort options: default*count    = number of times OCI procedure was executedcpu      = cpu time in seconds executingelapsed  = elapsed time in seconds executingdisk  

9、;   = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call*BEGIN D

10、BMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;call     count       cpu    elapsed       disk      query    current        rows- -&#

11、160; - - - - -  -Parse        2      0.00       0.00          0          0       

12、;   0           0Execute      2      0.00       0.00          0        

13、0; 0          0           2Fetch        0      0.00       0.00         

14、; 0          0          0           0- -  - - - - -  -total        4      0.00  

15、     0.00          0          0          0           2Misses in library cache during parse: 0Op

16、timizer mode: ALL_ROWSParsing user id: 51Elapsed times include waiting on following events:  Event waited on                             Times  

17、Max. Wait  Total Waited  -   Waited  -  -  SQL*Net message to client                       2        0.00  

18、0;       0.00  SQL*Net message from client                     2        5.60         

19、 7.74*select count(*)from tcall     count       cpu    elapsed       disk      query    current        rows- -  - - - -

20、-  -Parse        1      0.00       0.00          0          0         

21、 0           0Execute      1      0.00       0.00          0          0 

22、60;        0           0Fetch        2     10.94      10.68     222186     222957  &#

23、160;       0           1- -  - - - - -  -total        4     10.94      10.68     222186    

24、; 222957          0           1Misses in library cache during parse: 0Optimizer mode: ALL_ROWSParsing user id: 51Rows     Row Source Operation-  -      1&#

25、160; SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)100000000   INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)Elapsed times include waiting on following events:  Event waited on         &#

26、160;                   Times   Max. Wait  Total Waited  -   Waited  -  -  SQL*Net message to client           

27、            3        0.00          0.00  SQL*Net message from client               &#

28、160;     3        0.00          0.00  db file scattered read                      14249

29、60;       0.00          1.10  db file sequential read                        59    &#

30、160;   0.00          0.00*OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk     

31、query    current        rows- -  - - - - -  -Parse        3      0.00       0.00          0  &#

32、160;       0          0           0Execute      3      0.00       0.00    &

33、#160;     0          0          0           2Fetch        2     10.94  

34、0;   10.68     222186     222957          0           1- -  - - - - -  -total        8    

35、 10.94      10.68     222186     222957          0           3Misses in library cache during parse: 0Elapsed times include waiting on follow

36、ing events:  Event waited on                             Times   Max. Wait  Total Waited  -   Waited  -  -  SQ

37、L*Net message to client                       5        0.00          0.00  SQL*Net message from client

38、60;                    5        5.60          7.74  db file scattered read       

39、0;              14249        0.00          1.10  db file sequential read             

40、           59        0.00          0.00OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu  &#

41、160; elapsed       disk      query    current        rows- -  - - - - -  -Parse        0      0.00    

42、60;  0.00          0          0          0           0Execute      0   

43、;   0.00       0.00          0          0          0           0Fetch 

44、       0      0.00       0.00          0          0          0   

45、        0- -  - - - - -  -total        0      0.00       0.00          0        

46、  0          0           0Misses in library cache during parse: 0    3  user  SQL statements in session.    0  internal SQL statements in session. 

47、60;  3  SQL statements in session.*Trace file: ora10g_ora_21213.trcTrace file compatibility: 10.01.00Sort options: default       1  session in tracefile.       3  user  SQL statements in trace file.   

48、;    0  internal SQL statements in trace file.       3  SQL statements in trace file.       2  unique SQL statements in trace file.   14392  lines in trace file.      16&

49、#160; elapsed seconds in trace file.3.对上面的TKPROF格式化输出内容重点内容“解剖麻雀”正式开始1）摘录第一部分，SQL语句的执行情况总览select count(*)from tcall     count       cpu    elapsed       disk      query &

50、#160;  current        rows- -  - - - - -  -Parse        1      0.00       0.00          0    &#

51、160;     0          0           0Execute      1      0.00       0.00      &

52、#160;   0          0          0           0Fetch        2     10.94    

53、0; 10.68     222186     222957          0           1- -  - - - - -  -total        4     10.94 

54、     10.68     222186     222957          0           1关于统计表格的标题信息中count、cpu、elapsed、disk、query、current和rows的说明在该trace文件的最前端有一个简要的说明，这里再分别赘述一下。co

55、unt   ：查询在此阶段执行的次数；cpu     ：该查询在此阶段的CPU时间量，以毫秒为单位；elapsed ：花费在此阶段上的挂钟时间，该值比cpu值大的时候，表明存在等待事件；disk    ：执行物理I/O次数；query   ：在意一致性检索方式获得块时，执行逻辑I/O次数；current ：逻辑I/O次数；rows    ：此阶段，被处理或受影响的行数。关于第一列的赘述：Parse   ：软编译和硬编译次数；Execut

56、e ：在open和execute语句中完成的内容;Fetch   ：select中会有数据显示，在update语句中不会有数据显示。2）摘录运行环境信息Misses in library cache during parse: 0Optimizer mode: ALL_ROWSParsing user id: 51第一行的“0”表示查询使用的是软解析（soft parse）。优化模式是：ALL_ROWS使用最后一行的用户ID可以获得执行时的会话信息。获得用户信息可以通过下面的SQL语句完成。sysora10g> select * from all_users wher

57、e user_id = 51;USERNAME                          USER_ID CREATED- - -SEC                 &

58、#160;                  51 2009-10-15 13:04:033）摘录执行计划信息Rows     Row Source Operation-  -      1  SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)100000000   INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)有趣发现：通过第二行可以得到这个t表的数据量，这里显示结果是1亿。“解剖”上面出现的几个重要参数：cr=222957          - 一致性读取pr=