使用10046跟踪并解读Trace文件内容

    首先来介绍一下10046 trace可以帮助我们做哪些事情。 10046 trace帮助我们解析 一条/多条SQL、PL/SQL语句的运行状态 ，这些状态包括 ：Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划，在library cache中解析情况等等。
    通过在session级别设置 ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER,LEVEL 12'  来开启SQL trace功能，然后在执行SQL、process或是语句，最后在SQL全部执行 ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'完成后关闭SQL TRACE功能。
在instance级别，我们在需要ALTER SYSTEM SET EVENT '10046 TRACE NAME CONTEXT FOREVER,LEVEL x'完成的。10046 trace是分级别的，这里就不解释了。
    下来来具体分析trace文件的内容，我们使用TKPROF工具格式trc文件，这样提高文件的易读性。

点击(此处)折叠或打开

1. TKPROF: Release 11.2.0.4.0 - Development on Sat Apr 16 13:56:18 2016
   
2. 
   
3. Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
   
4. 
   
5. Trace file: indsdb_ora_8130.trc
   
6. Sort options: default

  格式化后的文件开头会告诉我们什么信息呢？ 有oracle的版本及文件生成时间，分别是11.2.0.4.0和  Sat Apr 16 13:56:18 2016 ，还有就是有indsdb_ora_8130.trc这个trc文件生成的 。

点击(此处)折叠或打开

1. ********************************************************************************
   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
   ********************************************************************************
   select
       count(*),TEMPLATE_ID
   from
       record,outworker,organization
   where
       organization.enterprise_id = 'ff8080813d11e5d1013d85ed90e6736e' and
       organization.oid like 'a5a04237fcf34b81baaf0994cc1d7c9c' and
       outworker.organization_id=organization.id and outworker.id=record.operator_id and
       record.enterprise_id='ff8080813d11e5d1013d85ed90e6736e'
   group by
       record.TEMPLATE_ID
   
   
   call     count       cpu    elapsed       disk      query    current        rows
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   Parse        2      0.03       0.03          0          0          0           0
   Execute      2      0.00       0.00          0          0          0           0
   Fetch       18      2.53       2.53      32193      69037          0         230
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   total       22      2.56       2.56      32193      69037          0         230
   
   

    这段告诉我们是哪个SQL被trace，并解释SQL执行过程中占用资源的情况，分别在时间、CPU、消耗的物理读和逻辑读等信息。

点击(此处)折叠或打开

1. Misses in library cache during parse: 2
   Optimizer mode: ALL_ROWS
   Parsing user id: 94  (TESTTEMP)
   Number of plan statistics captured: 2
   
   Rows (1st) Rows (avg) Rows (max)  Row Source Operation
   ---------- ---------- ----------  ---------------------------------------------------
          115        115        115  HASH GROUP BY (cr=34518 pr=16096 pw=0 time=1266938 us cost=17 size=290 card=1)
      1930044    1930044    1930044   NESTED LOOPS  (cr=34518 pr=16096 pw=0 time=1347576 us cost=16 size=290 card=1)
         1323       1323       1323    NESTED LOOPS  (cr=918 pr=415 pw=0 time=39998 us cost=12 size=203 card=1)
            1          1          1     TABLE ACCESS BY INDEX ROWID ORGANIZATION (cr=178 pr=90 pw=0 time=4330 us cost=3 size=137 card=1)
          278        278        278      INDEX RANGE SCAN I_ORGAN_ENTERPRISE (cr=5 pr=2 pw=0 time=298 us cost=1 size=0 card=2)(object id 99390)
         1323       1323       1323     TABLE ACCESS BY INDEX ROWID OUTWORKER (cr=740 pr=326 pw=0 time=37082 us cost=9 size=792 card=12)
         1323       1323       1323      INDEX RANGE SCAN I_OUTWORKER_ORGID (cr=11 pr=6 pw=0 time=214 us cost=2 size=0 card=17)(object id 99406)
      1930044    1930044    1930044    INDEX RANGE SCAN I_RECORD_ENT_OPER_TEP (cr=33600 pr=15682 pw=0 time=974254 us cost=4 size=522 card=6)(object id 100404)
   
   Rows     Execution Plan
   -------  ---------------------------------------------------
         0  SELECT STATEMENT   MODE: ALL_ROWS
       115   HASH (GROUP BY)
   1930044    NESTED LOOPS
      1323     NESTED LOOPS
         1      TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
                    'ORGANIZATION' (TABLE)
       278       INDEX   MODE: ANALYZED (RANGE SCAN) OF 
                     'I_ORGAN_ENTERPRISE' (INDEX)
      1323      TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
                    'OUTWORKER' (TABLE)
      1323       INDEX   MODE: ANALYZED (RANGE SCAN) OF 
                     'I_OUTWORKER_ORGID' (INDEX)
   1930044     INDEX   MODE: ANALYZED (RANGE SCAN) OF 
                   'I_RECORD_ENT_OPER_TEP' (INDEX)
   

    Misses in library cache during parse 表示 SQL 执行硬解析的次数，Optimizer mode 表示优化器的模式，Number of plan statistics captured 表示执行计划采样是2次，
    在接下来就是告诉我们执行计划是什么样子的，分别在一致性读 cr、物理读pr、物理等待pw、消耗时间time-单位是microsecond、本次操作的优化器成本cost、数据源大小-字节size、优化器的基数card和oracle对象objetc id这些基本信息。
    其中，我们还看到了SQL的执行计划，通过Rows行看出本SQL访问的数据库对象以及读取的数据行数的多少。  

点击(此处)折叠或打开

1. Elapsed times include waiting on following events:
     Event waited on                             Times   Max. Wait  Total Waited
     ----------------------------------------   Waited  ----------  ------------
     SQL*Net message to client                      18        0.00          0.00
     Disk file operations I/O                        3        0.00          0.00
     db file sequential read                     31642        0.00          0.27
     db file parallel read                          30        0.00          0.00
     db file scattered read                          3        0.00          0.00
     SQL*Net message from client                    18        3.51          6.73
   ********************************************************************************
   

    接下来就是SQL执行过程中的等待事件，本示例花费times最多的等待事件是db file sequential read。db file sequential read 表示单块读等待，是一种比较常见的物理IO等待事件，这里的sequential表示把数据从物理磁盘读取到连续内存空间中，而不是表示读取的数据块是连续的。

点击(此处)折叠或打开

1. OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
   
   call     count       cpu    elapsed       disk      query    current        rows
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   Parse        4      0.03       0.03          0          0          0           0
   Execute      4      0.00       0.00          0          0          0           0
   Fetch       18      2.53       2.53      32193      69037          0         230
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   total       26      2.56       2.56      32193      69037          0         230
   
   Misses in library cache during parse: 2
   
   Elapsed times include waiting on following events:
     Event waited on                             Times   Max. Wait  Total Waited
     ----------------------------------------   Waited  ----------  ------------
     SQL*Net message to client                      20        0.00          0.00
     SQL*Net message from client                    20        5.64         16.79
     db file sequential read                     31642        0.00          0.27
     Disk file operations I/O                        3        0.00          0.00
     db file parallel read                          30        0.00          0.00
     db file scattered read                          3        0.00          0.00
   
   OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
   
   
   call     count       cpu    elapsed       disk      query    current        rows
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   Parse       18      0.00       0.00          0          0          0           0
   Execute    106      0.01       0.01          0          0          0           0
   Fetch      268      0.00       0.00         45        407          0         515
   ------- ------  -------- ---------- ---------- ---------- ----------  ----------
   total      392      0.02       0.02         45        407          0         515
   
   Misses in library cache during parse: 7
   Misses in library cache during execute: 7
   
   Elapsed times include waiting on following events:
     Event waited on                             Times   Max. Wait  Total Waited
     ----------------------------------------   Waited  ----------  ------------
     db file sequential read                        45        0.00          0.00
   
       4  user  SQL statements in session.
      19  internal SQL statements in session.
      23  SQL statements in session.
       1  statement EXPLAINed in this session.
   
   

上面是SQL整体的执行情况总计：OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS    表示数据字典相关信息     OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS    表示SQL递归调用相关信息

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/27039319/viewspace-2083309/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/27039319/viewspace-2083309/