使用 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 意思是解析的时候库缓存丢失游标, 也就是说发生了一次硬解析
