==============================================

http://blog.itpub.net/519536/viewspace-617071

==============================================

SELECT VALUE  FROM V$PARAMETER WHERE NAME = 'user_dump_dest

';--查看trace文件位置 /u01/admin/omrep/udump

alter session set timed_statistics=true;

alter session set events '10046 trace name context forever, level 12';

select sid, serial# from v$session;--SID=11，SERIAL=9726

开启：execute dbms_system.set_ev(11,9726,10046,12,'');

关闭：execute dbms_system.set_ev(11,9726,10046,0,'');

execute dbms_system.set_ev(158,28,10046,12,'');

授权：  grant execute on dbms_system to uat1;

创建同义词 ：CREATE SYNONYM DBMS_SYSTEM FOR SYS.DBMS_SYSTEM

execute dbms_system.set_ev(sid,serial#,10046,12,'');

alter session set events '10046 trace name context off';--关闭跟踪

tkprof  /u01/admin/omrep/udump/omrep_ora_2747.trc /u01/ora10g_ora_21213.trc 

tkprof d:\app\administrator\diag\rdbms\posprd\posprd\trace\posprd_ora_6924.trc D:\trace.txt record=D:\sql.txt sys=yes aggregate=yes

tkprof D:\app\Administrator\diag\rdbms\orcl\orcl\trace\orcl_dbrm_1412.trc D:\trace.txt record=D:\sql.txt sys=yes aggregate=yes

3.对上面的TKPROF格式化输出内容重点内容“解剖麻雀”正式开始
1）摘录第一部分，SQL语句的执行情况总览
select count(*)
from
 t


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     10.94      10.68     222186     222957          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     10.94      10.68     222186     222957          0           1

关于统计表格的标题信息中count、cpu、elapsed、disk、query、current和rows的说明在该trace文件的最前端有一个简要的说明，这里再分别赘述一下。
count   ：查询在此阶段执行的次数；
cpu     ：该查询在此阶段的CPU时间量，以毫秒为单位；
elapsed ：花费在此阶段上的挂钟时间，该值比cpu值大的时候，表明存在等待事件；
disk    ：执行物理I/O次数；
query   ：在意一致性检索方式获得块时，执行逻辑I/O次数；
current ：逻辑I/O次数；
rows    ：此阶段，被处理或受影响的行数。

关于第一列的赘述：
Parse   ：软编译和硬编译次数；
Execute ：在open和execute语句中完成的内容;
Fetch   ：select中会有数据显示，在update语句中不会有数据显示。

2）摘录运行环境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51

第一行的“0”表示查询使用的是软解析（soft parse）。
优化模式是：ALL_ROWS
使用最后一行的用户ID可以获得执行时的会话信息。获得用户信息可以通过下面的SQL语句完成。
sys@ora10g> select * from all_users where user_id = 51;

USERNAME                          USER_ID CREATED
------------------------------ ---------- -------------------
SEC                                    51 2009-10-15 13:04:03

3）摘录执行计划信息
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=222186          -- 物理读取
pw=0               -- 物理写
time=100000562 us  -- 占用时间，单位：微妙 百万分之一秒

4）摘录等待事件
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3        0.00          0.00
  db file scattered read                      14249        0.00          1.10
  db file sequential read                        59        0.00          0.00

通过这段等待事件的描述，可以清楚的得到在执行SQL语句的过程中都出现了哪些引人注目的等待事件。比如上面显示出的“db file scattered read”和“db file sequential read”信息，如果此类信息在生产环境中大量出现，就需要重点深入分析和研究了。

4.小结
整个“解剖麻雀”的过程到此告一段落，相信您对“10046跟踪”和TKPROF格式化有了一个整体上的了解，这里只是通过一个示例来展示一下trace跟踪和TKPROF的强大。更重要的是在生产环境故障诊断过程中的具体问题具体分析。这里不得不提醒一下的是，在生产环境中使用10046 level 12方法对会话进行跟踪时，要充分考虑到它对系统性能的影响，前期测试是必须的步骤。

-- The End --