使用 10046 查看执行计划并读懂 trace 文件
来源:互联网 发布:sql如何创建数据库 编辑:程序博客网 时间:2024/04/28 01:34
使用 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 文件的完整路径.
刚刚提到的 oradebug 激活跟踪 10046 事件, 我想大部分 dba 都会使用. oradebug 是个功能强大非常好用的工具, 使用 oradebug help 将会看到它的功能很多
其中, 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的基础上增加绑定变量和等待事件的信息 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
nam an event that we waited for 等待事件 ela 此操作消耗的时间 p3 block 块号 trm timestamp 时间戳 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
tkprof 翻译的 trace 文件的汇总报表如下:
一般来说, 使用 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
- 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'
接着, 下面的语句说明了 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
最后显示的是该游标的执行计划
- 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
例如, 执行步骤 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
0 0
- 使用 10046 查看执行计划并读懂 trace 文件
- 使用 10046 查看执行计划并读懂 trace 文件
- 10046入门:使用 10046 查看执行计划并读懂 trace文件
- 使用trace跟踪sql语句执行计划
- 读懂执行计划
- 读懂MySQL执行计划
- 读懂 MySQL 执行计划
- 读懂 MySQL 执行计划
- 使用命令行查看执行计划
- teradata EXPLAIN 读懂关键字--读懂执行计划
- 使用oradebug 查看当前trace 文件位置
- 10046trace 中不显示执行计划的解决方案
- 查看trace文件信息
- trace文件路径查看
- Oracle 查看trace文件
- 使用dbms_xplan工具查看执行计划
- 使用dbms_xplan工具查看执行计划
- MySQL使用explain查看执行计划
- webgoat实验记录
- 国家实施兽药二维码追溯系统的重大意义
- org.tinygroup.databasebuinstaller-数据库结构及元数据自动创建
- Java内部类小结
- org.tinygroup.dbrouter-数据库分区分表
- 使用 10046 查看执行计划并读懂 trace 文件
- JavaScript、js数组的基本操作
- centOs 安装redis,集群
- UVA 10655 Contemplation! Algebra (矩阵快速幂)
- NSTimer解除循环引用
- printf、sprintf与fprintf
- weblogic学习
- org.tinygroup.metadata-元数据定义
- STL学习笔记之容器--vector(一)