|
【赛迪网－it技术报道】sql_trace、access path和db_file_multiblock_read_count的实际应用。
测试环境：winxp、oracle9.2
sql> create table t as select * from dba_objects;
table created.
sql> select count(*) from t;
count(*)
----------
30536
sql> select file_id,block_id,blocks from dba_extents where segment_name='t';
file_id block_id blocks
---------- ---------- ----------
1 50921 8
1 50929 8
1 51233 8
1 51241 8
1 51249 8
1 51257 8
1 51265 8
1 51273 8
1 51281 8
1 51289 8
1 51297 8
file_id block_id blocks
---------- ---------- ----------
1 51305 8
1 51313 8
1 51321 8
1 51329 8
1 51337 8
1 51465 128
1 51593 128
1 51721 128
19 rows selected.
sql> show parameter db_file
name type value
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 16
db_file_name_convert string
db_files integer 200
sql> alter session set events '10046 trace name context off';
至此，得到下面的结果，采用的是全表扫描，共扫描了5次。
其中p1是文件号，p2起始块号，p3读取数据块数量。
*** 2006-04-21 11:49:30.000
=====================
parsing in cursor #1 len=68 dep=0 uid=0 oct=42 lid=0 tim=2925420357 hv=570864185 ad='668b0b0c'
alter session set events '10046 trace name context forever,level 12'
end of stmt
exec #1:c=0,e=156,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=2925420341
wait #1: nam='sql*net message to client' ela= 10 p1=1111838976 p2=1 p3=0
wait #1: nam='sql*net message from client' ela= 6417020 p1=1111838976 p2=1 p3=0
=====================
parsing in cursor #1 len=22 dep=0 uid=0 oct=3 lid=0 tim=2931845333 hv=2199322426 ad='6710b08c'
select count(*) from t
end of stmt
parse #1:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2931845326
binds #1:
exec #1:c=0,e=1534,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2931853164
wait #1: nam='sql*net message to client' ela= 9 p1=1111838976 p2=1 p3=0
wait #1: nam='db file scattered read' ela= 8813 p1=1 p2=51677 p3=16
wait #1: nam='db file scattered read' ela= 1307 p1=1 p2=51693 p3=16
wait #1: nam='db file scattered read' ela= 5570 p1=1 p2=51709 p3=12
wait #1: nam='db file scattered read' ela= 2616 p1=1 p2=51729 p3=13
wait #1: nam='db file scattered read' ela= 595 p1=1 p2=51749 p3=6
fetch #1:c=15625,e=36032,p=63,cr=421,cu=0,mis=0,r=1,dep=0,og=4,tim=2931890915
wait #1: nam='sql*net message from client' ela= 409 p1=1111838976 p2=1 p3=0
fetch #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=2931893361
wait #1: nam='sql*net message to client' ela= 4 p1=1111838976 p2=1 p3=0
*** 2006-04-21 11:49:52.000
wait #1: nam='sql*net message from client' ela= 15276041 p1=1111838976 p2=1 p3=0
stat #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='sort aggregate '
stat #1 id=2 cnt=30536 pid=1 pos=1 obj=31687 op='table access full t '
=====================
parsing in cursor #1 len=55 dep=0 uid=0 oct=42 lid=0 tim=2947176010 hv=3381932903 ad='668aba24'
alter session set events '10046 trace name context off'
end of stmt
parse #1:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2947176003
binds #1:
exec #1:c=0,e=857,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2947181612
重新创建一个表空间，其类型为uniform size为1m，在oracle9.2默认的表空间类型是autoallocate:
sql> create tablespace test datafile 'd:\oracle\oradata\orcl\test.dbf' size 100m
extent management local uniform size 1m;
tablespace created.
sql> alter table t move tablespace test;
table altered.
sql> select file_id,block_id,blocks from dba_extents where segment_name='t';
file_id block_id blocks
---------- ---------- ----------
15 9 128
15 137 128
15 265 128
15 393 128
sql> show parameter read_co
name type value
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 16
sql> alter session set db_file_multiblock_read_count=128;
session altered.
sql> show parameter read_co
name type value
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 128
sql> alter session set events '10046 trace name context forever,level 12';
session altered.
sql> select count(*) from t;
count(*)
----------
30536
sql> alter session set events '10046 trace name context off';
session altered.
sql> alter session set events '10046 trace name context forever,level 12';
session altered.
sql> select count(object_id) from t;
count(object_id)
----------------
30536
sql> alter session set events '10046 trace name context off';
session altered.
*** 2006-04-21 11:57:30.000
=====================
parsing in cursor #1 len=68 dep=0 uid=0 oct=42 lid=0 tim=3404883601 hv=570864185 ad='668b0b0c'
alter session set events '10046 trace name context forever,level 12'
end of stmt
exec #1:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3404883596
wait #1: nam='sql*net message to client' ela= 7 p1=1111838976 p2=1 p3=0
wait #1: nam='sql*net message from client' ela= 8723581 p1=1111838976 p2=1 p3=0
=====================
parsing in cursor #1 len=22 dep=0 uid=0 oct=3 lid=0 tim=3413615443 hv=2199322426 ad='6710b08c'
select count(*) from t
end of stmt
parse #1:c=0,e=791,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=3413615434
binds #1:
exec #1:c=0,e=962,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3413622098
wait #1: nam='sql*net message to client' ela= 6 p1=1111838976 p2=1 p3=0
wait #1: nam='db file scattered read' ela= 26551 p1=15 p2=10 p3=127
wait #1: nam='db file scattered read' ela= 21707 p1=15 p2=137 p3=128
wait #1: nam='db file scattered read' ela= 21034 p1=15 p2=265 p3=128
wait #1: nam='db file scattered read' ela= 6274 p1=15 p2=393 p3=34
fetch #1:c=31250,e=94765,p=417,cr=421,cu=0,mis=0,r=1,dep=0,og=4,tim=3413718512
wait #1: nam='sql*net message from client' ela= 405 p1=1111838976 p2=1 p3=0
fetch #1:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=3413721284
wait #1: nam='sql*net message to client' ela= 5 p1=1111838976 p2=1 p3=0
*** 2006-04-21 11:58:34.000
wait #1: nam='sql*net message from client' ela= 55266334 p1=1111838976 p2=1 p3=0
stat #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='sort aggregate '
=====================
parsing in cursor #2 len=116 dep=1 uid=0 oct=3 lid=0 tim=3468993615 hv=189272129 ad='672eea30'
select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.dataobj#,o.flags from obj$ o where o.obj#=:1
end of stmt
parse #2:c=0,e=148,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3468993604
binds #2:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=05f4a0cc bln=22 avl=04 flg=05
value=31687
exec #2:c=0,e=3824,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=3469002280
fetch #2:c=0,e=78,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=3469003223
stat #1 id=2 cnt=30536 pid=1 pos=1 obj=31687 op='table access full t '
=====================
parsing in cursor #1 len=55 dep=0 uid=0 oct=42 lid=0 tim=3469005223 hv=3381932903 ad='668aba24'
alter session set events '10046 trace name context off'
end of stmt
parse #1:c=0,e=86,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3469005215
binds #1:
exec #1:c=0,e=806,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3469009599
sql> alter session set events '10046 trace name context forever,level 12';
session altered.
sql> select count(object_id) from t;
count(object_id)
----------------
30536
sql> alter session set events '10046 trace name context off';
session altered.
*** 2006-04-21 14:00:39.000
=====================
parsing in cursor #1 len=68 dep=0 uid=0 oct=42 lid=0 tim=3146410393 hv=570864185 ad='668b0b0c'
alter session set events '10046 trace name context forever,level 12'
end of stmt
exec #1:c=0,e=25200,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3146410376
wait #1: nam='sql*net message to client' ela= 13714 p1=1111838976 p2=1 p3=0
*** 2006-04-21 14:01:05.000
wait #1: nam='sql*net message from client' ela= 25992096 p1=1111838976 p2=1 p3=0
=====================
parsing in cursor #1 len=30 dep=0 uid=0 oct=3 lid=0 tim=3172483520 hv=3181685953 ad='66484f6c'
select count(object_id) from t
end of stmt
parse #1:c=0,e=19961,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=3172483510
binds #1:
exec #1:c=0,e=34883,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3172522525
wait #1: nam='sql*net message to client' ela= 8 p1=1111838976 p2=1 p3=0
wait #1: nam='db file scattered read' ela= 221317 p1=15 p2=10 p3=127
wait #1: nam='db file scattered read' ela= 63377 p1=15 p2=137 p3=128
wait #1: nam='db file scattered read' ela= 70986 p1=15 p2=265 p3=128
wait #1: nam='db file scattered read' ela= 4848 p1=15 p2=393 p3=34
fetch #1:c=93750,e=390135,p=417,cr=420,cu=0,mis=0,r=1,dep=0,og=4,tim=3172914415
wait #1: nam='sql*net message from client' ela= 18930 p1=1111838976 p2=1 p3=0
fetch #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=3172936022
wait #1: nam='sql*net message to client' ela= 4 p1=1111838976 p2=1 p3=0
wait #1: nam='sql*net message from client' ela= 3671714 p1=1111838976 p2=1 p3=0
stat #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='sort aggregate '
stat #1 id=2 cnt=30536 pid=1 pos=1 obj=31687 op='table access full t '
=====================
parsing in cursor #1 len=55 dep=0 uid=0 oct=42 lid=0 tim=3176627539 hv=3381932903 ad='668aba24'
alter session set events '10046 trace name context off'
end of stmt
parse #1:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3176627528
binds #1:
exec #1:c=0,e=889,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3176633060
sql> create unique index idx_t_id on t (object_id);
index created.
sql> alter session set events '10046 trace name context forever,level 12';
session altered.
sql> select count(object_id) from t where object_id>0;
count(object_id)
----------------
30536
sql> alter session set events '10046 trace name context off';
session altered.
此种情况说明使用了不合理的索引，此时索引使用的是index range扫描方式，从另一个方面也阐述了"db file sequential read"的产生原理。
*** 2006-04-21 14:01:55.000
=====================
parsing in cursor #1 len=68 dep=0 uid=0 oct=42 lid=0 tim=3222433563 hv=570864185 ad='668b0b0c'
alter session set events '10046 trace name context forever,level 12'
end of stmt
exec #1:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3222433552
wait #1: nam='sql*net message to client' ela= 5 p1=1111838976 p2=1 p3=0
*** 2006-04-21 14:02:09.000
wait #1: nam='sql*net message from client' ela= 14067572 p1=1111838976 p2=1 p3=0
=====================
parsing in cursor #1 len=48 dep=0 uid=0 oct=3 lid=0 tim=3236513737 hv=1107120101 ad='677ffa8c'
select count(object_id) from t where object_id>0
end of stmt
parse #1:c=0,e=1716,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=3236513728
binds #1:
exec #1:c=0,e=944,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3236519497
wait #1: nam='sql*net message to client' ela= 7 p1=1111838976 p2=1 p3=0
wait #1: nam='db file sequential read' ela= 12439 p1=1 p2=50923 p3=1
wait #1: nam='db file sequential read' ela= 203 p1=1 p2=50924 p3=1
wait #1: nam='db file sequential read' ela= 158 p1=1 p2=50925 p3=1
wait #1: nam='db file sequential read' ela= 157 p1=1 p2=50926 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=50927 p3=1
wait #1: nam='db file sequential read' ela= 149 p1=1 p2=50928 p3=1
wait #1: nam='db file sequential read' ela= 156 p1=1 p2=50929 p3=1
wait #1: nam='db file sequential read' ela= 150 p1=1 p2=50930 p3=1
wait #1: nam='db file sequential read' ela= 148 p1=1 p2=50931 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=50932 p3=1
wait #1: nam='db file sequential read' ela= 167 p1=1 p2=50933 p3=1
wait #1: nam='db file sequential read' ela= 156 p1=1 p2=50934 p3=1
wait #1: nam='db file sequential read' ela= 147 p1=1 p2=50935 p3=1
wait #1: nam='db file sequential read' ela= 149 p1=1 p2=50936 p3=1
wait #1: nam='db file sequential read' ela= 1330 p1=1 p2=51233 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51234 p3=1
wait #1: nam='db file sequential read' ela= 149 p1=1 p2=51235 p3=1
wait #1: nam='db file sequential read' ela= 142 p1=1 p2=51236 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51237 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51238 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51239 p3=1
wait #1: nam='db file sequential read' ela= 146 p1=1 p2=51240 p3=1
wait #1: nam='db file sequential read' ela= 203 p1=1 p2=51241 p3=1
wait #1: nam='db file sequential read' ela= 158 p1=1 p2=51242 p3=1
wait #1: nam='db file sequential read' ela= 158 p1=1 p2=51243 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51244 p3=1
wait #1: nam='db file sequential read' ela= 158 p1=1 p2=51245 p3=1
wait #1: nam='db file sequential read' ela= 154 p1=1 p2=51246 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51247 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51248 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51249 p3=1
wait #1: nam='db file sequential read' ela= 172 p1=1 p2=51250 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51251 p3=1
wait #1: nam='db file sequential read' ela= 213 p1=1 p2=51252 p3=1
wait #1: nam='db file sequential read' ela= 166 p1=1 p2=51253 p3=1
wait #1: nam='db file sequential read' ela= 156 p1=1 p2=51254 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51255 p3=1
wait #1: nam='db file sequential read' ela= 154 p1=1 p2=51256 p3=1
wait #1: nam='db file sequential read' ela= 156 p1=1 p2=51257 p3=1
wait #1: nam='db file sequential read' ela= 154 p1=1 p2=51258 p3=1
wait #1: nam='db file sequential read' ela= 171 p1=1 p2=51259 p3=1
wait #1: nam='db file sequential read' ela= 156 p1=1 p2=51260 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51261 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=51262 p3=1
wait #1: nam='db file sequential read' ela= 149 p1=1 p2=51263 p3=1
wait #1: nam='db file sequential read' ela= 147 p1=1 p2=51264 p3=1
wait #1: nam='db file sequential read' ela= 150 p1=1 p2=51265 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=51266 p3=1
wait #1: nam='db file sequential read' ela= 140 p1=1 p2=51267 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=51268 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51269 p3=1
wait #1: nam='db file sequential read' ela= 146 p1=1 p2=51270 p3=1
wait #1: nam='db file sequential read' ela= 148 p1=1 p2=51271 p3=1
wait #1: nam='db file sequential read' ela= 199 p1=1 p2=51272 p3=1
wait #1: nam='db file sequential read' ela= 158 p1=1 p2=51273 p3=1
wait #1: nam='db file sequential read' ela= 154 p1=1 p2=51274 p3=1
wait #1: nam='db file sequential read' ela= 154 p1=1 p2=51275 p3=1
wait #1: nam='db file sequential read' ela= 153 p1=1 p2=51276 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=51277 p3=1
wait #1: nam='db file sequential read' ela= 152 p1=1 p2=51278 p3=1
wait #1: nam='db file sequential read' ela= 151 p1=1 p2=51279 p3=1
wait #1: nam='db file sequential read' ela= 150 p1=1 p2=51280 p3=1
wait #1: nam='db file sequential read' ela= 148 p1=1 p2=51281 p3=1
fetch #1:c=15625,e=102159,p=63,cr=64,cu=0,mis=0,r=1,dep=0,og=4,tim=3236628878
wait #1: nam='sql*net message from client' ela= 382 p1=1111838976 p2=1 p3=0
fetch #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=3236631569
wait #1: nam='sql*net message to client' ela= 4 p1=1111838976 p2=1 p3=0
wait #1: nam='sql*net message from client' ela= 3303736 p1=1111838976 p2=1 p3=0
stat #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='sort aggregate '
stat #1 id=2 cnt=30536 pid=1 pos=1 obj=31689 op='index range scan idx_t_id '
=====================
parsing in cursor #1 len=55 dep=0 uid=0 oct=42 lid=0 tim=3239940284 hv=3381932903 ad='668aba24'
alter session set events '10046 trace name context off'
end of stmt
parse #1:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3239940275
binds #1:
exec #1:c=0,e=1028,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3239947806
sql> analyze table t compute statistics;
table analyzed.
sql> alter session set events '10046 trace name context forever,level 12';
session altered.
sql> select count(object_id) from t where object_id>0;
count(object_id)
----------------
30536
sql> alter session set events '10046 trace name context off';
session altered.
这个现象说明假如表是被分析过的话，采用的就是cbo：
*** 2006-04-21 14:10:18.000
=====================
parsing in cursor #1 len=68 dep=0 uid=0 oct=42 lid=0 tim=3724965605 hv=570864185 ad='668b0b0c'
alter session set events '10046 trace name context forever,level 12'
end of stmt
exec #1:c=0,e=153,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3724965598
wait #1: nam='sql*net message to client' ela= 7 p1=1111838976 p2=1 p3=0
*** 2006-04-21 14:10:28.000
wait #1: nam='sql*net message from client' ela= 10044728 p1=1111838976 p2=1 p3=0
=====================
parsing in cursor #1 len=48 dep=0 uid=0 oct=3 lid=0 tim=3735044065 hv=1107120101 ad='677ffa8c'
select count(object_id) from t where object_id>0
end of stmt
parse #1:c=0,e=18398,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=3735044052
binds #1:
exec #1:c=0,e=908,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3735050327
wait #1: nam='sql*net message to client' ela= 5 p1=1111838976 p2=1 p3=0
fetch #1:c=15625,e=16491,p=0,cr=68,cu=0,mis=0,r=1,dep=0,og=4,tim=3735068413
wait #1: nam='sql*net message from client' ela= 470 p1=1111838976 p2=1 p3=0
fetch #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=3735071416
wait #1: nam='sql*net message to client' ela= 6 p1=1111838976 p2=1 p3=0
wait #1: nam='sql*net message from client' ela= 3767452 p1=1111838976 p2=1 p3=0
stat #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='sort aggregate '
stat #1 id=2 cnt=30536 pid=1 pos=1 obj=31690 op='index fast full scan idx_t_id '
=====================
parsing in cursor #1 len=55 dep=0 uid=0 oct=42 lid=0 tim=3738845289 hv=3381932903 ad='668aba24'
alter session set events '10046 trace name context off'
end of stmt
parse #1:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3738845282
binds #1:
exec #1:c=0,e=876,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3738850186
|
