使用TKPROF格式化TRACE输出之解剖麻雀.docx

1、使用TKPROF格式化TRACE输出之解剖麻雀【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工具能提供更多的有意义的信息，方便性能诊断secora

2、10g alter session 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 f

3、ile启用SQL_TRACE，并捕捉跟踪文件中的绑定变量；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 sessi

4、on set events 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, serial# from v$session;B.开启

5、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(*)-1000000005）关闭当前会话的跟踪secora10g alter session set events 10046 trace name c

6、ontext off;Session altered.2.在udump目录中找到刚刚生成的trace文件（关于如何快速获得生成的trace文件的方法有很多种，选择一个适合自己的就OK），并使用TKPROF对其进行格式化，然后打印一下全部输出，后面将对每一个输出项做一下“解剖麻雀”:)ora10gsecDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prfTKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04

7、: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 (c) 1982, 2005, Oracle. All rights reserved.Trace file: ora10g_ora_21213.trcSort optio

8、ns: default*count = number of times OCI procedure was executedcpu = cpu time in seconds executingelapsed = elapsed time in seconds executingdisk = number of physical reads of buffers from diskquery = number of buffers gotten for consistent readcurrent = number of buffers gotten in current mode (usua

9、lly for update)rows = number of rows processed by the fetch or execute call*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 0Execute 2 0.00 0.00 0 0 0 2Fetch 0 0.00 0.00 0 0 0 0- - - - - - - -total 4 0.00 0.00 0

10、 0 0 2Misses in library cache during parse: 0Optimizer mode: ALL_ROWSParsing user id: 51Elapsed 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 5.60 7.74*select count(*)fromtcall

11、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 10.94 10.68 222186 222957 0 1- - - - - - - -total 4 10.94 10.68 222186 222957 0 1Misses in library cache during parse: 0Optimizer mode: ALL_ROWSParsing user id: 51Rows Row Source Operation- - 1 SO