使用 10046 查看执行计划并读懂 trace 文件

查看 sql 执行计划的方法有许多种, 10046 事件就是其中的一种. 与其他查看 sql 执行计划不同, 当我们遇到比较复杂的 sql 语句, 我们可以通过 10046 跟踪 sql 得到执行计划中每一个步骤的逻辑读, 物理读以及花费的时间等. 这种细粒度的跟踪对于我们分析 sql 性能尤其有用.

一般来说, 使用 10046 事件得到 sql 执行计划的步骤如下:

1. 激活当前 session 10046 事件

2. 在当前 session 中执行 sql 语句

3. 关闭当前 session 10046 事件

执行完上述步骤后, 通常会自动生成一个 trace 文件. 在 oracle 11g 中, trace 文件一般放在$ORACLE_BASE/diag/rdbms/{database_name}/$ORACLE_SID/trace 目录下. 如果使用 oradebug 激活跟踪 10046后,
可以使用 oradebug tracefile_name 得到刚刚生成的 trace 文件的完整路径.

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
background_dump_dest                 string      g:\app\davidd\diag\rdbms\david
                                                 \david\trace

刚刚提到的 oradebug 激活跟踪 10046 事件, 我想大部分 dba 都会使用. oradebug 是个功能强大非常好用的工具, 使用 oradebug help 将会看到它的功能很多

SQL> oradebug help
HELP           [command]                 		Describe one or all commands
SETMYPID                                 		Debug current process
SETOSPID       <ospid>                   		Set OS pid of process to debug
SETORAPID      <orapid> ['force']        		Set Oracle pid of process to debug
SETORAPNAME    <orapname>                		Set Oracle process name to debug
SHORT_STACK                              		Get abridged OS stack
CURRENT_SQL                              		Get current SQL
DUMP           <dump_name> <lvl> [addr]  		Invoke named dump
DUMPSGA        [bytes]                   		Dump fixed SGA
DUMPLIST                                 		Print a list of available dumps
EVENT          <text>                    		Set trace event in process
SESSION_EVENT  <text>                    		Set trace event in session
DUMPVAR        <p|s|uga> <name> [level]  		Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE       <address> <type> <count>  		Print/dump an address with type info
SETVAR         <p|s|uga> <name> <value>  		Modify a fixed PGA/SGA/UGA variable
PEEK           <addr> <len> [level]      		Print/Dump memory
POKE           <addr> <len> <value>      		Modify memory
WAKEUP         <orapid>                  		Wake up Oracle process
SUSPEND                                  		Suspend execution
RESUME                                   		Resume execution
FLUSH                                    		Flush pending writes to trace file
CLOSE_TRACE                              		Close trace file
TRACEFILE_NAME                           		Get name of trace file
LKDEBUG                                  		Invoke global enqueue service debugger
NSDBX                                    		Invoke CGS name-service debugger
-G             <Inst-List | def | all>   		Parallel oradebug command prefix
-R             <Inst-List | def | all>   		Parallel oradebug prefix (return output
SETINST        <instance# .. | all>      		Set instance list in double quotes
SGATOFILE      <SGA dump dir>            		Dump SGA to file; dirname in double quotes
DMPCOWSGA      <SGA dump dir> 		 		Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA      <SGA dump dir>            		Map SGA as COW; dirname in double quotes
HANGANALYZE    [level] [syslevel]        		Analyze system hang
FFBEGIN                                  		Flash Freeze the Instance
FFDEREGISTER                             		FF deregister instance from cluster
FFTERMINST                               		Call exit and terminate instance
FFRESUMEINST                             		Resume the flash frozen instance
FFSTATUS                                 		Flash freeze status of instance
SKDSTTPCS      <ifname>  <ofname>        		Helps translate PCs to names
WATCH          <address> <len> <self|exist|all|target>  Watch a region of memory
DELETE         <local|global|target> watchpoint <id>    Delete a watchpoint
SHOW           <local|global|target> watchpoints        Show  watchpoints
DIRECT_ACCESS  <set/enable/disable command | select query> Fixed table access
CORE                                     		Dump core without crashing process
IPC                                      		Dump ipc information
UNLIMIT                                  		Unlimit the size of the trace file
PROCSTAT                                 		Dump process statistics
CALL           <func> [arg1] ... [argn]  		Invoke function with arguments

使用 oradebug 跟踪 10046 命令如下:

SQL> oradebug setmypid
Statement processed.

// 激活 10046 事件
SQL> oradebug event 10046 trace name context forever,level 12;
Statement processed.

SQL> select /*+ leading(t3) use_merge(t4) */ *
  2  from t3, t4
  3  where t3.id = t4.t3_id and t3.n = 1100;

10 rows selected.

// 在当前 session 关闭 10046 事件
SQL> oradebug event 10046 trace name context off;
Statement processed.

// 使用 oradebug tracefile_name 可以直接看到生成的 trace 文件的位置
SQL> oradebug tracefile_name;
g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc

其中, 10046 按照收集信息的内容分为以下等级:

 Level 0  停用SQL跟踪，相当于SQL_TRACE=FALSE
 Level 1  标准SQL跟踪，相当于SQL_TRACE=TRUE
 Level 4  在level 1的基础上增加绑定变量的信息
 Level 8  在level 1的基础上增加等待事件的信息
 Level 12  在level 1的基础上增加绑定变量和等待事件的信息

分析读懂 trace 文件

现在我们打开 g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc 看看生成的 trace 文件的内容

<pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql" style="font-size:14px;">PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'
select /*+ leading(t3) use_merge(t4) */ *
from t3, t4
where t3.id = t4.t3_id and t3.n = 1100
END OF STMT
PARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319
EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482
WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512
FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462
WAIT #22: nam='SQL*Net message from client' ela= 221 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947755
WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947803
FETCH #22:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=3831111046,tim=900460947864
STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'
STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'
STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'
STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'
STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000)'

从上面的 trace 文件我们可以看出 sql 语句经过了 parse(解析) -> exec(执行) -> fetch(从游标中获取数据) 几个过程, 其中第一句说明了当前跟踪执行的 sql 语句的概况,比如使用游标号, sql 语句的长度, 递归深度等等基本信息:

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'
 cursor  cursor number
 len  sql 语句长度
 dep  sql 语句递归深度
 uid  user id
 oct  oracle command type
 lid  privilege user id
 tim  timestamp，时间戳
 hv  hash id
 ad  sql address 地址, 用在 v$sqltext
 sqlid  sql id

接着, 下面的语句说明了 sql 语句具体的执行过程以及每一个步骤消耗 CPU 的时间等性能指标

PARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319
EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482
FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462
 c  CPU 消耗的时间
 e  Elapsed time 
 p  number of physical reads 物理读的次数
 cr  number of buffers retrieved for CR reads   逻辑读的数据块
 cu  number of buffers retrieved in current mode (current 模式读取的数据块)
 mis  cursor missed in the cache 库缓存中丢失的游标, 硬解析次数
 r  number of rows processed 处理的行数
 dep  递归深度
 og  optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
 plh  plan hash value
 tim  timestamp 时间戳

以及执行过程中的发生的等待事件

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512
 nam  an event that we waited for 等待事件
 ela  此操作消耗的时间
 p3  block 块号
 trm  timestamp 时间戳

最后显示的是该游标的执行计划

STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'
STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'
STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'
STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'
STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000
 cnt  当前行源返回的行数
 pid  parent id of this row source 当前行源的父结点 id
 pos  position in explain plan 执行计划的位置
 obj  object id of row source (if this is a base object)
 op   the row source access operation

例如, 执行步骤 merge join 消耗的逻辑读为 119, 物理读为 0, 耗费的时间为 28 us, 成本 cost 193，返回 10 条记录

使用 tkprof 命令翻译 trace 文件

我们也可以使用 tkprof 命令对 trace 文件进行翻译，得到一个容易理解的 trace 汇总报表文件

C:\Documents and Settings\davidd> tkprof g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc d:\trace.trc

TKPROF: Release 11.2.0.1.0 - Development on Thu Dec 18 18:51:44 2014

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

tkprof 翻译的 trace 文件的汇总报表如下：

Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc
Sort options: default

********************************************************************************
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 /*+ leading(t3) use_merge(t4) */ *
from t3, t4
where t3.id = t4.t3_id and t3.n = 1100

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      0.00       0.00          0        119          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0        119          0          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
     10  MERGE JOIN  (cr=119 pr=0 pw=0 time=0 us cost=193 size=1280 card=10)
      1   SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)
      1    TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)
     10   SORT JOIN (cr=104 pr=0 pw=0 time=0 us cost=187 size=650000 card=10000)
  10000    TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8733 us cost=29 size=650000 card=10000)

Elapsed 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       20.23         20.23

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

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      0.00       0.00          0        119          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0        119          0          10

Misses in library cache during parse: 1

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       20.23         30.20

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

    1  user  SQL statements in session.
    0  internal SQL statements in session.
    1  SQL statements in session.
********************************************************************************
Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       1  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       1  SQL statements in trace file.
       1  unique SQL statements in trace file.
     122  lines in trace file.
       0  elapsed seconds in trace file.

其中，Misses in library cache during parse ：1   意思是解析的时候库缓存丢失游标,  也就是说发生了一次硬解析

参考: http://www.eygle.com/archives/2005/10/aeearaw_traceia.html

时间： 2024-10-12 06:44:59

使用 10046 查看执行计划并读懂 trace 文件的相关文章

10046入门:使用 10046 查看执行计划并读懂 trace文件

************************************************************* 1.开启10046 ************************************************************* SQL> oradebug setmypid Statement processed. // 激活 10046 事件 SQL> oradebug event 10046 trace name context forever,lev

Oracle数据库查看执行计划

基于ORACLE的应用系统很多性能问题,是由应用系统SQL性能低劣引起的,所以,SQL的性能优化很重要,分析与优化SQL的性能我们一般通过查看该SQL的执行计划,本文就如何看懂执行计划,以及如何通过分析执行计划对SQL进行优化做相应说明. 一.什么是执行计划(explain plan) 执行计划:一条查询语句在ORACLE中的执行过程或访问路径的描述. 二.如何查看执行计划 1: 在PL/SQL下按F5查看执行计划.第三方工具toad等. 很多人以为PL/SQL的执行计划只能看到基数.优化器.耗

oracle如何查看执行计划

1.在PL/SQL Developer中得到一个SQL的执行计划 输入想要查看执行计划的目标SQL,再按一下快捷键F5就可以了.2.explain plan 命令 explain plan for + 目标SQL select * from table(dbms_xplan.display)3. DBMS_XPLAN 包 1) select * from table(dbms_xplan.display_cursor(null,null,'advanced')) 它用于在SQLPLUS中查看刚刚

简单对比查看执行计划的两种方法EXPLAIN PLAN 和 AUTOTRACE

EXPLAIN PLAN 和 AUTOTRACE 都可以查看执行计划. 值得一提的是:前者只是优化器通过读取数据字典的统计信息做出'最佳'访问路径判断,并没有真正去执行语句:后者是实际去执行了SQL语句,同时把访问记录数.执行计划.统计信息等打印出来. 下面粘出实验结果加以说明,注意对比两者的耗时: <p>SQL> CONNECT /AS SYSDBA Connected.</p><p>SQL> SET LINESIZE 300; SQL> SET T

T-SQL备忘(5)：查看执行计划

先理解几个概念:表扫描.聚集索引扫描.聚集索引查找.索引扫描.书签查找. [查看执行计划] 在理解概念之前先得知道如何查看执行计划—Ctrl+L.如下图: 注:SQL Server的执行计划是从右向左看的. [理解几个概念] 1.表扫描(Table scan):发生于堆表,并且没有可用的索引可用时,会发生表扫描,表示整个表扫描一次. select * from T_UserInfo 查看执行计划如下: 2.聚集索引扫描(Clustered Index Scan):发生于聚集表,也相当于全表扫描操

创建跟踪和查看执行计划需要的权限

多看书,多积累,温故知新.只有要用的时候,才会发现知识欠缺.不要说知道有这么回事,要很有底气的回答应该怎么做.查看跟踪和查看执行计划需要怎样的权限?sysadmin/db_owner肯定可以,但不应该给这么大的权限.创建登录名 --create login use master go create login TracePlan with password='123qwe' go 创建用户 --create user use AdventureWorks2008R2 go create user

如何查看执行计划

SSMS里的设置方法就不多说了上图看 如何以SQL命令的方式查看执行计划: 一.查看实际的执行计划 方式一,查看文本格式 SET STATISTICS PROFILE ON; SET STATISTICS PROFILE OFF; 方式二.查看XML格式(可点击转到图形界面查看,因为类似全屏,界面比较大,对于比较大的执行计划会有用些) SET STATISTICS XML ON; SET STATISTICS XML OFF; 二.查看估计的执行计划 方式一,查看全部 SET SHOWPLAN_

hive高阶1--sql和hive语句执行顺序、explain查看执行计划、group by生成MR

hive语句执行顺序 msyql语句执行顺序 代码写的顺序: select ... from... where.... group by... having... order by.. 或者 from ... select ... 代码的执行顺序: from... where...group by... having.... select ... order by... hive 语句执行顺序 大致顺序 from... where.... select...group by... having

Mongodb查看执行计划和强制索引策略

查看执行计划的方法:explain () winningPlan是最终的执行计划 其中的indexBounds索引计划 在age上建立索引 > db.person.ensureIndex({age:1}); {    "createdCollectionAutomatically" : false,    "numIndexesBefore" : 1,    "numIndexesAfter" : 2,    "ok"