藉助10053跟蹤事件理解SQL執行過程
今天在膝上型電腦上對10053跟蹤事件進行了測試，發現跟蹤檔案無論在內容或註釋方面都有了明顯的改進，而且增加了執行計劃。
看了一遍後對SQL的執行過程（尤其是join order）有了進一步的認識。具體執行過程如下：
SYSTEM@kuqlan10>alter session set events '10053 trace name context forever,level 2';
會話已更改。
SYSTEM@kuqlan10>select d.deptno,d.dname,e.ename,e.job
2 from scott.dept d,scott.emp e
3 where d.deptno=e.deptno
4 and e.ename='SCOTT';
DEPTNO DNAME ENAME JOB
---------- -------------- ---------- ---------
20 RESEARCH SCOTT ANALYST
SYSTEM@kuqlan10>
Trace檔案的內容如下，作為今後複習在此將重要部分貼上出來了。
*** 2011-08-26 19:31:06.640
*** ACTION NAME:() 2011-08-26 19:31:06.625
*** MODULE NAME:(SQL*Plus) 2011-08-26 19:31:06.625
*** SERVICE NAME:(SYS$USERS) 2011-08-26 19:31:06.625
*** SESSION ID:(158.37) 2011-08-26 19:31:06.625
Registered qb: SEL$1 0x4efa6b4 (PARSER)
signature (): qb_name=SEL$1 nbfros=2 flg=0
fro(0): flg=4 objn=51149 hint_alias="D"@"SEL$1"
fro(1): flg=4 objn=51151 hint_alias="E"@"SEL$1"
**************************
Predicate Move-Around (PM)
**************************
PM: Considering predicate move-around in SEL$1 (#0).
PM: Checking validity of predicate move-around in SEL$1 (#0).
CBQT: Validity checks failed for 0w80r07zg7d8y.
CVM: Considering view merge in query block SEL$1 (#0)
Query block (04EFA6B4) before join elimination:
SQL:******* UNPARSED QUERY IS *******
SELECT "D"."DEPTNO" "DEPTNO","D"."DNAME" "DNAME","E"."ENAME" "ENAME","E"."JOB" "JOB" FROM "SCOTT"."DEPT" "D","SCOTT"."EMP" "E" WHERE "D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
Query block (04EFA6B4) unchanged
CBQT: Validity checks failed for 0w80r07zg7d8y.
***************
Subquery Unnest
***************
SU: Considering subquery unnesting in query block SEL$1 (#0)
*************************
Set-Join Conversion (SJC)
*************************
SJC: Considering set-join conversion in SEL$1 (#0).
**************************
Predicate Move-Around (PM)
**************************
PM: Considering predicate move-around in SEL$1 (#0).
PM: Checking validity of predicate move-around in SEL$1 (#0).
PM: PM bypassed: Outer query contains no views.
FPD: Considering simple filter push in SEL$1 (#0)
FPD: Current where clause predicates in SEL$1 (#0) :
"D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
kkogcp: try to generate transitive predicate from check constraints for SEL$1 (#0)
predicates with check contraints: "D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
after transitive predicate generation: "D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
finally: "D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
apadrv-start: call(in-use=340, alloc=0), compile(in-use=35140, alloc=0)
kkoqbc-start
: call(in-use=344, alloc=0), compile(in-use=35924, alloc=0)
******************************************
Current SQL statement for this session:
select d.deptno,d.dname,e.ename,e.job
from scott.dept d,scott.emp e
where d.deptno=e.deptno
and e.ename='SCOTT'
*******************************************
Legend
The following abbreviations are used by optimizer trace.
CBQT - cost-based query transformation
JPPD - join predicate push-down
FPD - filter push-down
PM - predicate move-around
CVM - complex view merging
SPJ - select-project-join
SJC - set join conversion
SU - subquery unnesting
OBYE - order by elimination
ST - star transformation
qb - query block
LB - leaf blocks
DK - distinct keys
LB/K - average number of leaf blocks per key
DB/K - average number of data blocks per key
CLUF - clustering factor
NDV - number of distinct values
Resp - response cost
Card - cardinality
Resc - resource cost
NL - nested loops (join)
SM - sort merge (join)
HA - hash (join)
CPUCSPEED - CPU Speed
IOTFRSPEED - I/O transfer speed
IOSEEKTIM - I/O seek time
SREADTIM - average single block read time
MREADTIM - average multiblock read time
MBRC - average multiblock read count
MAXTHR - maximum I/O system throughput
SLAVETHR - average slave I/O throughput
dmeth - distribution method
1: no partitioning required
2: value partitioned
4: right is random (round-robin)
512: left is random (round-robin)
8: broadcast right and partition left
16: broadcast left and partition right
32: partition left using partitioning of right
64: partition right using partitioning of left
128: use hash partitioning dimension
256: use range partitioning dimension
2048: use list partitioning dimension
1024: run the join in serial
0: invalid distribution method
sel - selectivity
ptn - partition
*******************************************
Peeked values of the binds in SQL statement
*******************************************
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
*************************************
PARAMETERS WITH ALTERED VALUES
******************************
*************************************
PARAMETERS WITH DEFAULT VALUES
******************************
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
parallel_execution_enabled = true
parallel_query_forced_dop = 0
parallel_dml_forced_dop = 0
parallel_ddl_forced_degree = 0
………
_optimizer_self_induced_cache_cost = false
_optimizer_min_cache_blocks = 10
_optimizer_or_expansion = depth
_optimizer_order_by_elimination_enabled = true
_optimizer_outer_to_anti_enabled = true
_selfjoin_mv_duplicates = true
_dimension_skip_null = true
_force_rewrite_enable = false
_optimizer_star_tran_in_with_clause = true
_optimizer_complex_pred_selectivity = true
_gby_hash_aggregation_enabled = true
***************************************
PARAMETERS IN OPT_PARAM HINT
****************************
***************************************
Column Usage Monitoring is ON: tracking level = 1
***************************************
****************
QUERY BLOCK TEXT
****************
select d.deptno,d.dname,e.ename,e.job
from scott.dept d,scott.emp e
where d.deptno=e.deptno
and e.ename='SCOTT'
*********************
QUERY BLOCK SIGNATURE
*********************
qb name was generated
signature (optimizer): qb_name=SEL$1 nbfros=2 flg=0
fro(0): flg=0 objn=51149 hint_alias="D"@"SEL$1"
fro(1): flg=0 objn=51151 hint_alias="E"@"SEL$1"
*****************************
SYSTEM STATISTICS INFORMATION
*****************************
Using NOWORKLOAD Stats
CPUSPEED: 485 millions instruction/sec
IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
IOSEEKTIM: 10 milliseconds (default is 10)
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: EMP Alias: E
#Rows: 14 #Blks: 5 AvgRowLen: 37.00
Column (#8): DEPTNO(NUMBER)
AvgLen: 3.00 NDV: 3 Nulls: 0 Density: 0.33333 Min: 10 Max: 30
Index Stats::
Index: PK_EMP Col#: 1
LVLS: 0 #LB: 1 #DK: 14 LB/K: 1.00 DB/K: 1.00 CLUF: 1.00
***********************
Table Stats::
Table: DEPT Alias: D
#Rows: 4 #Blks: 5 AvgRowLen: 20.00
Column (#1): DEPTNO(NUMBER)
AvgLen: 3.00 NDV: 4 Nulls: 0 Density: 0.25 Min: 10 Max: 40
Index Stats::
Index: PK_DEPT Col#: 1
LVLS: 0 #LB: 1 #DK: 4 LB/K: 1.00 DB/K: 1.00 CLUF: 1.00
***************************************
SINGLE TABLE ACCESS PATH
Table: DEPT Alias: D
Card: Original: 4 Rounded: 4 Computed: 4.00 Non Adjusted: 4.00
Access Path: TableScan
Cost: 3.01 Resp: 3.01 Degree: 0
Cost_io: 3.00 Cost_cpu: 36287
Resp_io: 3.00 Resp_cpu: 36287
Best:: AccessPath: TableScan
Cost: 3.01 Degree: 1 Resp: 3.01 Card: 4.00 Bytes: 0
***************************************
SINGLE TABLE ACCESS PATH
Column (#2): ENAME(VARCHAR2)
AvgLen: 6.00 NDV: 14 Nulls: 0 Density: 0.071429
Table: EMP Alias: E
Card: Original: 14 Rounded: 1 Computed: 1.00 Non Adjusted: 1.00
Access Path: TableScan
Cost: 3.01 Resp: 3.01 Degree: 0
Cost_io: 3.00 Cost_cpu: 38807
Resp_io: 3.00 Resp_cpu: 38807
Best:: AccessPath: TableScan
Cost: 3.01 Degree: 1 Resp: 3.01 Card: 1.00 Bytes: 0
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
***********************
Join order[1]: EMP[E]#0 DEPT[D]#1
***************
Now joining: DEPT[D]#1
***************
NL Join
Outer table: Card: 1.00 Cost: 3.01 Resp: 3.01 Degree: 1 Bytes: 17
Inner table: DEPT Alias: D
Access Path: TableScan
NL Join: Cost: 6.01 Resp: 6.01 Degree: 0
Cost_io: 6.00 Cost_cpu: 75094
Resp_io: 6.00 Resp_cpu: 75094
Access Path: index (UniqueScan)
Index: PK_DEPT
resc_io: 1.00 resc_cpu: 8341
ix_sel: 0.25 ix_sel_with_filters: 0.25 --Effective Idex/Table Selectivity
NL Join: Cost: 4.01 Resp: 4.01 Degree: 1
Cost_io: 4.00 Cost_cpu: 47149
Resp_io: 4.00 Resp_cpu: 47149
Access Path: index (AllEqUnique)
Index: PK_DEPT
resc_io: 1.00 resc_cpu: 8341
ix_sel: 0.25 ix_sel_with_filters: 0.25
NL Join: Cost: 4.01 Resp: 4.01 Degree: 1
Cost_io: 4.00 Cost_cpu: 47149
Resp_io: 4.00 Resp_cpu: 47149
Best NL cost: 4.01
resc: 4.01 resc_io: 4.00 resc_cpu: 47149
resp: 4.01 resp_io: 4.00 resp_cpu: 47149
Join Card: 1.00 = outer (1.00) * inner (4.00) * sel (0.25)
Join Card - Rounded: 1 Computed: 1.00
SM Join
Outer table:
resc: 3.01 card 1.00 bytes: 17 deg: 1 resp: 3.01
Inner table: DEPT Alias: D
resc: 3.01 card: 4.00 bytes: 13 deg: 1 resp: 3.01
using dmeth: 2 #groups: 1
SORT resource Sort statistics
Sort width: 231 Area size: 202752 Max Area size: 40684544
Degree: 1
Blocks to Sort: 1 Row size: 29 Total Rows: 1
Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
Total IO sort cost: 0 Total CPU sort cost: 5819699
Total Temp space used: 0
SORT resource Sort statistics
Sort width: 231 Area size: 202752 Max Area size: 40684544
Degree: 1
Blocks to Sort: 1 Row size: 25 Total Rows: 4
Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
Total IO sort cost: 0 Total CPU sort cost: 5820060
Total Temp space used: 0
SM join: Resc: 8.01 Resp: 8.01 [multiMatchCost=0.00]
SM cost: 8.01
resc: 8.01 resc_io: 6.00 resc_cpu: 11714854
resp: 8.01 resp_io: 6.00 resp_cpu: 11714854
HA Join
Outer table:
resc: 3.01 card 1.00 bytes: 17 deg: 1 resp: 3.01
Inner table: DEPT Alias: D
resc: 3.01 card: 4.00 bytes: 13 deg: 1 resp: 3.01
using dmeth: 2 #groups: 1
Cost per ptn: 0.50 #ptns: 1
hash_area: 0 (max=0) Hash join: Resc: 6.51 Resp: 6.51 [multiMatchCost=0.00]
HA cost: 6.51
resc: 6.51 resc_io: 6.00 resc_cpu: 2985494
resp: 6.51 resp_io: 6.00 resp_cpu: 2985494
Best:: JoinMethod: NestedLoop
Cost: 4.01 Degree: 1 Resp: 4.01 Card: 1.00 Bytes: 30
***********************
Best so far: Table#: 0 cost: 3.0067 card: 1.0000 bytes: 17
Table#: 1 cost: 4.0081 card: 1.0000 bytes: 30
***********************
Join order[2]: DEPT[D]#1 EMP[E]#0
***************
Now joining: EMP[E]#0
***************
NL Join
Outer table: Card: 4.00 Cost: 3.01 Resp: 3.01 Degree: 1 Bytes: 13
Inner table: EMP Alias: E
Access Path: TableScan
NL Join: Cost: 9.03 Resp: 9.03 Degree: 0
Cost_io: 9.00 Cost_cpu: 197756
Resp_io: 9.00 Resp_cpu: 197756
Best NL cost: 9.03 --注意該Cost值大於第一種join order，因此最終會被放棄
resc: 9.03 resc_io: 9.00 resc_cpu: 197756
resp: 9.03 resp_io: 9.00 resp_cpu: 197756
Join Card: 1.00 = outer (4.00) * inner (1.00) * sel (0.25)
Join Card - Rounded: 1 Computed: 1.00
SM Join
Outer table:
resc: 3.01 card 4.00 bytes: 13 deg: 1 resp: 3.01
Inner table: EMP Alias: E
resc: 3.01 card: 1.00 bytes: 17 deg: 1 resp: 3.01
using dmeth: 2 #groups: 1
SORT resource Sort statistics
Sort width: 231 Area size: 202752 Max Area size: 40684544
Degree: 1
Blocks to Sort: 1 Row size: 25 Total Rows: 4
Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
Total IO sort cost: 0 Total CPU sort cost: 5820060
Total Temp space used: 0
SORT resource Sort statistics
Sort width: 231 Area size: 202752 Max Area size: 40684544
Degree: 1
Blocks to Sort: 1 Row size: 29 Total Rows: 1
Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
Total IO sort cost: 0 Total CPU sort cost: 5819699
Total Temp space used: 0
SM join: Resc: 8.01 Resp: 8.01 [multiMatchCost=0.00]
SM cost: 8.01
resc: 8.01 resc_io: 6.00 resc_cpu: 11714854
resp: 8.01 resp_io: 6.00 resp_cpu: 11714854
SM Join (with index on outer)
Access Path: index (FullScan)
Index: PK_DEPT
resc_io: 2.00 resc_cpu: 15723
ix_sel: 1 ix_sel_with_filters: 1
Cost: 2.00 Resp: 2.00 Degree: 1
Outer table:
resc: 2.00 card 4.00 bytes: 13 deg: 1 resp: 2.00
Inner table: EMP Alias: E
resc: 3.01 card: 1.00 bytes: 17 deg: 1 resp: 3.01
using dmeth: 2 #groups: 1
SORT resource Sort statistics
Sort width: 231 Area size: 202752 Max Area size: 40684544
Degree: 1
Blocks to Sort: 1 Row size: 29 Total Rows: 1
Initial runs: 1 Merge passes: 0 IO Cost / pass: 0
Total IO sort cost: 0 Total CPU sort cost: 5819699
Total Temp space used: 0
SM join: Resc: 6.01 Resp: 6.01 [multiMatchCost=0.00]
HA Join
Outer table:
resc: 3.01 card 4.00 bytes: 13 deg: 1 resp: 3.01
Inner table: EMP Alias: E
resc: 3.01 card: 1.00 bytes: 17 deg: 1 resp: 3.01
using dmeth: 2 #groups: 1
Cost per ptn: 0.50 #ptns: 1
hash_area: 0 (max=0) Hash join: Resc: 6.51 Resp: 6.51 [multiMatchCost=0.00]
HA cost: 6.51
resc: 6.51 resc_io: 6.00 resc_cpu: 2985644
resp: 6.51 resp_io: 6.00 resp_cpu: 2985644
Join order aborted: cost > best plan cost
***********************
(newjo-stop-1) k:0, spcnt:0, perm:2, maxperm:2000
*********************************
Number of join permutations tried: 2 --嘗試了兩種連結順序
*********************************
(newjo-save) [0 1 ]
Final - All Rows Plan: Best join order: 1
Cost: 4.0081 Degree: 1 Card: 1.0000 Bytes: 30
Resc: 4.0081 Resc_io: 4.0000 Resc_cpu: 47149
Resp: 4.0081 Resp_io: 4.0000 Resc_cpu: 47149
kkoipt: Query block SEL$1 (#0)
******* UNPARSED QUERY IS *******
SELECT "D"."DEPTNO" "DEPTNO","D"."DNAME" "DNAME","E"."ENAME" "ENAME","E"."JOB" "JOB" FROM "SCOTT"."DEPT" "D","SCOTT"."EMP" "E" WHERE "D"."DEPTNO"="E"."DEPTNO" AND "E"."ENAME"='SCOTT'
kkoqbc-end
: call(in-use=33408, alloc=0), compile(in-use=36892, alloc=0)
apadrv-end: call(in-use=33408, alloc=0), compile(in-use=37480, alloc=0)
sql_id=0w80r07zg7d8y.
Current SQL statement for this session:
select d.deptno,d.dname,e.ename,e.job
from scott.dept d,scott.emp e
where d.deptno=e.deptno
and e.ename='SCOTT'
============
Plan Table
============
------------------------------------------------+-----------------------------------+
| Id | Operation | Name| Rows| Bytes | Cost | Time |
------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 4 | |
| 1 | NESTED LOOPS | | 1 | 30 | 4 | 00:00:01 |
| 2 | TABLE ACCESS FULL | EMP | 1 | 17 | 3 | 00:00:01 |
| 3 | TABLE ACCESS BY INDEX ROWID | DEPT | 1 | 13 | 1 | 00:00:01 |
| 4 | INDEX UNIQUE SCAN | PK_DEPT | 1 | | 0 | |
------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - filter("E"."ENAME"='SCOTT')
4 - access("D"."DEPTNO"="E"."DEPTNO")
Content of other_xml column
===========================
db_version : 10.2.0.1
parse_schema : SYSTEM
plan_hash : 351108634
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('10.2.0.1')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "E"@"SEL$1")
INDEX(@"SEL$1" "D"@"SEL$1" ("DEPT"."DEPTNO"))
LEADING(@"SEL$1" "E"@"SEL$1" "D"@"SEL$1")
USE_NL(@"SEL$1" "D"@"SEL$1")
END_OUTLINE_DATA
*/
Optimizer environment:
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
………
_optimizer_complex_pred_selectivity = true
_gby_hash_aggregation_enabled = true
Query Block Registry:
*********************
SEL$1 0x4efa6b4 (PARSER) [FINAL]
Optimizer State Dump: call(in-use=38888, alloc=0), compile(in-use=57392, alloc=0)
如果會採用3個表的連結查詢，會出現更多的連結順序（Join order）,在此過程我們可以體會到最佳化的工作多不容易。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/18841027/viewspace-1054425/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 【10053 事件】10053事件的跟蹤檔案解析事件
- MYSQL sql執行過程的一些跟蹤分析(一)MySql
- 透過10053事件分析一個SQL執行計劃事件SQL
- MYSQL sql執行過程的一些跟蹤分析(二.mysql優化器追蹤分析)MySql優化
- 跟蹤客戶端執行的SQL客戶端SQL
- 使用sqltrace跟蹤session執行的sqlSQLSession
- 理解oracle執行sql語句的過程OracleSQL
- 使用10053事件跟蹤CBO優化器決策（上）事件優化
- 使用10053事件跟蹤CBO優化器決策（下）事件優化
- mysql如何跟蹤執行的sql語句MySql
- sql 執行過程SQL
- sql_trace 和 events 跟蹤事件SQL事件
- 跟蹤SQL - SQL Trace 及 10046 事件SQL事件
- PostgreSQL 原始碼解讀（15）- Insert語句(執行過程跟蹤)SQL原始碼
- 使用10046事件跟蹤分析執行計劃事件
- SQLServer進行SQL跟蹤SQLServer
- sql執行過程分析SQL
- 跟蹤執行命令T
- SQL調整優化與10053跟蹤分析一例SQL優化
- 10046事件跟蹤會話sql事件會話SQL
- 收集 SQL Server 事件探查器跟蹤資訊SQLServer事件
- SQLNET跟蹤tnsping過程SQL
- 0624使用10035事件跟蹤無法執行的sql語句事件SQL
- 【索引】分割槽表索引重建過程的10704事件跟蹤索引事件
- SQL調整優化與10053跟蹤分析一例(zt)SQL優化
- Oracle執行語句跟蹤 使用sql trace實現語句追蹤OracleSQL
- 用SQL Server事件探查器Profiler建立跟蹤SQLServer事件
- [zt] oracle跟蹤檔案與跟蹤事件Oracle事件
- oracle跟蹤檔案與跟蹤事件(zt)Oracle事件
- oracle跟蹤檔案和跟蹤事件(zt)Oracle事件
- 藉助babel理解jsxBabelJS
- 透過ORADEBUG運用10046事件跟蹤SQL語句事件SQL
- 【TRACE】Oracle跟蹤事件Oracle事件
- Oracle 跟蹤事件【轉】Oracle事件
- 防止SQL SERVER的事件探查器跟蹤軟體SQLServer事件
- 一條Sql的執行過程SQL
- mysql執行sql語句過程MySql
- 使用SQL_TEACE的跟蹤檔案分析執行計劃SQL