通过10046分析SQL语句的执行计划、等待事件
程序员文章站
2022-03-24 14:02:13
本例子通过一个10046跟踪，分析sql语句的执行计划，等待事件等等。
--创建测试用表
conn bb/oracle
create table t as select * from dba_...
本例子通过一个10046跟踪，分析sql语句的执行计划，等待事件等等。
--创建测试用表
conn bb/oracle create table t as select * from dba_objects; select file_id,block_id,blocks from dba_extents where segment_name='t';
-- 查看该表的信息
bb@test>select file_id,block_id,blocks from dba_extents where segment_name='t';
file_id block_id blocks
---------- ---------- ----------
4 3280 8
4 3288 8
4 3296 8
4 3304 8
4 3312 8
4 3320 8
4 4480 8
4 4488 8
4 4496 8
4 4504 8
4 4512 8
file_id block_id blocks
---------- ---------- ----------
4 4520 8
4 4528 8
4 4536 8
4 4544 8
4 4552 8
4 4608 128
4 10624 128
4 10752 128
4 10880 128
4 11008 128
4 11136 128
file_id block_id blocks
---------- ---------- ----------
4 11264 128
4 11392 128
4 11520 128
4 68832 8
4 68840 8
4 68848 8
4 69048 8
4 69056 8
4 69064 8
4 69072 8
4 69080 8
file_id block_id blocks
---------- ---------- ----------
4 69088 8
4 69096 8
4 69104 8
4 69112 8
4 69120 8
4 69128 8
4 69136 8
4 69376 8
4 11648 128
4 11776 128
4 11904 128
file_id block_id blocks
---------- ---------- ----------
4 12032 128
4 12800 128
4 12928 128
4 13056 128
4 13184 128
4 13312 128
4 259544 8
4 259552 8
4 259560 8
4 259568 8
4 259576 8
file_id block_id blocks
---------- ---------- ----------
4 26752 8
4 26760 8
4 26768 8
4 26776 8
4 26784 8
4 26792 8
4 26800 8
4 26808 8
4 26816 8
4 26824 8
4 26832 8
file_id block_id blocks
---------- ---------- ----------
4 26880 128
4 27008 128
4 27136 128
4 27264 128
4 27392 128
4 27520 128
4 27648 128
4 27776 128
4 27904 128
4 28032 128
4 28160 128
file_id block_id blocks
---------- ---------- ----------
4 28288 128
4 28416 128
4 28544 128
4 28672 128
4 28800 128
4 28928 128
4 29056 128
4 29184 128
4 29312 128
4 29440 128
4 29568 128
file_id block_id blocks
---------- ---------- ----------
4 29696 128
4 29824 128
4 29952 128
4 30080 128
4 30208 128
4 30336 128
4 30464 128
4 30592 128
4 30720 128
4 30848 128
4 30976 128
file_id block_id blocks
---------- ---------- ----------
4 31104 128
4 31232 128
4 31360 128
4 31488 128
4 31616 128
4 31744 128
4 31872 128
4 32000 128
4 32128 128
4 32256 128
4 32384 128
file_id block_id blocks
---------- ---------- ----------
4 32512 128
4 32640 128
4 32768 128
4 32896 128
4 33024 128
4 33152 128
4 33280 128
4 33408 128
4 33536 128
4 33664 128
4 33792 128
file_id block_id blocks
---------- ---------- ----------
4 33920 128
4 34048 128
4 34176 128
4 34304 128
4 34432 128
4 34560 128
4 34688 128
4 34816 128
4 34944 1024
4 35968 1024
4 36992 1024
file_id block_id blocks
---------- ---------- ----------
4 38016 1024
4 39040 1024
4 40064 1024
4 41088 1024
4 42112 1024
4 43136 1024
4 44160 1024
4 45184 1024
4 46208 1024
4 47232 1024
4 48256 1024
file_id block_id blocks
---------- ---------- ----------
4 49280 1024
4 50304 1024
4 51328 1024
4 52352 1024
4 53376 1024
4 54400 1024
4 55424 1024
4 56448 1024
151 rows selected.
-- 进行10046跟踪
alter session set events '10046 trace name context forever,level 12'; select count(*) from t; alter session set events '10046 trace name context off';
-- 查看跟踪结果
[oracle@test trace]$ cat test_ora_6737.trc | grep scatt wait #139968888163696: nam='db file scattered read' ela= 12166 file#=4 block#=69073 blocks=7 obj#=91583 tim=1531903907293546 wait #139968888163696: nam='db file scattered read' ela= 11848 file#=4 block#=69105 blocks=7 obj#=91583 tim=1531903907317393 wait #139968888163696: nam='db file scattered read' ela= 11287 file#=4 block#=69137 blocks=7 obj#=91583 tim=1531903907340915 wait #139968888163696: nam='db file scattered read' ela= 11618 file#=4 block#=11654 blocks=8 obj#=91583 tim=1531903907352627 wait #139968888163696: nam='db file scattered read' ela= 12236 file#=4 block#=11667 blocks=8 obj#=91583 tim=1531903907364974 wait #139968888163696: nam='db file scattered read' ela= 6046 file#=4 block#=11685 blocks=8 obj#=91583 tim=1531903907371152 wait #139968888163696: nam='db file scattered read' ela= 1276 file#=4 block#=11707 blocks=8 obj#=91583 tim=1531903907372514 wait #139968888163696: nam='db file scattered read' ela= 1111 file#=4 block#=11715 blocks=8 obj#=91583 tim=1531903907373686 wait #139968888163696: nam='db file scattered read' ela= 1086 file#=4 block#=11726 blocks=8 obj#=91583 tim=1531903907374848 wait #139968888163696: nam='db file scattered read' ela= 1141 file#=4 block#=11746 blocks=8 obj#=91583 tim=1531903907376058 wait #139968888163696: nam='db file scattered read' ela= 4574 file#=4 block#=11785 blocks=8 obj#=91583 tim=1531903907381818 wait #139968888163696: nam='db file scattered read' ela= 6874 file#=4 block#=11826 blocks=8 obj#=91583 tim=1531903907388753 wait #139968888163696: nam='db file scattered read' ela= 2303 file#=4 block#=11836 blocks=8 obj#=91583 tim=1531903907391154 wait #139968888163696: nam='db file scattered read' ela= 2256 file#=4 block#=11890 blocks=8 obj#=91583 tim=1531903907393506 wait #139968888163696: nam='db file scattered read' ela= 895 file#=4 block#=11898 blocks=6 obj#=91583 tim=1531903907394460 wait #139968888163696: nam='db file scattered read' ela= 4994 file#=4 block#=11912 blocks=8 obj#=91583 tim=1531903907399489 wait #139968888163696: nam='db file scattered read' ela= 5733 file#=4 block#=11938 blocks=8 obj#=91583 tim=1531903907405322 wait #139968888163696: nam='db file scattered read' ela= 1461 file#=4 block#=11960 blocks=8 obj#=91583 tim=1531903907406866 wait #139968888163696: nam='db file scattered read' ela= 1259 file#=4 block#=11968 blocks=8 obj#=91583 tim=1531903907408540 wait #139968888163696: nam='db file scattered read' ela= 51320 file#=4 block#=11999 blocks=8 obj#=91583 tim=1531903907459924 wait #139968888163696: nam='db file scattered read' ela= 14250 file#=4 block#=12087 blocks=8 obj#=91583 tim=1531903907485841 wait #139968888163696: nam='db file scattered read' ela= 3782 file#=4 block#=12105 blocks=8 obj#=91583 tim=1531903907489674 wait #139968888163696: nam='db file scattered read' ela= 1103 file#=4 block#=12116 blocks=8 obj#=91583 tim=1531903907490822 wait #139968888163696: nam='db file scattered read' ela= 992 file#=4 block#=12136 blocks=8 obj#=91583 tim=1531903907491951 wait #139968888163696: nam='db file scattered read' ela= 10666 file#=4 block#=12835 blocks=8 obj#=91583 tim=1531903907502673 wait #139968888163696: nam='db file scattered read' ela= 12443 file#=4 block#=12846 blocks=8 obj#=91583 tim=1531903907515161 wait #139968888163696: nam='db file scattered read' ela= 3487 file#=4 block#=12872 blocks=8 obj#=91583 tim=1531903907518988 wait #139968888163696: nam='db file scattered read' ela= 1371 file#=4 block#=12898 blocks=8 obj#=91583 tim=1531903907520437 wait #139968888163696: nam='db file scattered read' ela= 7641 file#=4 block#=12934 blocks=8 obj#=91583 tim=1531903907529697 wait #139968888163696: nam='db file scattered read' ela= 8794 file#=4 block#=12945 blocks=8 obj#=91583 tim=1531903907538551 wait #139968888163696: nam='db file scattered read' ela= 3783 file#=4 block#=12980 blocks=8 obj#=91583 tim=1531903907542381 wait #139968888163696: nam='db file scattered read' ela= 3494 file#=4 block#=12995 blocks=8 obj#=91583 tim=1531903907545934 wait #139968888163696: nam='db file scattered read' ela= 1096 file#=4 block#=13023 blocks=8 obj#=91583 tim=1531903907547085 wait #139968888163696: nam='db file scattered read' ela= 936 file#=4 block#=13039 blocks=8 obj#=91583 tim=1531903907548063 wait #139968888163696: nam='db file scattered read' ela= 10117 file#=4 block#=13065 blocks=8 obj#=91583 tim=1531903907559100 wait #139968888163696: nam='db file scattered read' ela= 6004 file#=4 block#=13074 blocks=8 obj#=91583 tim=1531903907565148 wait #139968888163696: nam='db file scattered read' ela= 954 file#=4 block#=13107 blocks=8 obj#=91583 tim=1531903907566178 wait #139968888163696: nam='db file scattered read' ela= 810 file#=4 block#=13127 blocks=8 obj#=91583 tim=1531903907567033 wait #139968888163696: nam='db file scattered read' ela= 828 file#=4 block#=13147 blocks=8 obj#=91583 tim=1531903907567907 wait #139968888163696: nam='db file scattered read' ela= 888 file#=4 block#=13160 blocks=8 obj#=91583 tim=1531903907568855 wait #139968888163696: nam='db file scattered read' ela= 8524 file#=4 block#=13225 blocks=8 obj#=91583 tim=1531903907577541 wait #139968888163696: nam='db file scattered read' ela= 5665 file#=4 block#=13246 blocks=8 obj#=91583 tim=1531903907583250 wait #139968888163696: nam='db file scattered read' ela= 1015 file#=4 block#=13268 blocks=8 obj#=91583 tim=1531903907584308 wait #139968888163696: nam='db file scattered read' ela= 1003 file#=4 block#=13282 blocks=8 obj#=91583 tim=1531903907588421 wait #139968888163696: nam='db file scattered read' ela= 1004 file#=4 block#=13296 blocks=8 obj#=91583 tim=1531903907589665 wait #139968888163696: nam='db file scattered read' ela= 11494 file#=4 block#=13337 blocks=8 obj#=91583 tim=1531903907601207 wait #139968888163696: nam='db file scattered read' ela= 6378 file#=4 block#=13361 blocks=8 obj#=91583 tim=1531903907607631 [oracle@test trace]$
-- tkprof格式化的部分内容：
sql id: cyzznbykb509s plan hash: 2966233522
select count(*)
from
t
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
parse 1 0.00 0.00 0 1 0 0
execute 1 0.00 0.00 0 0 0 0
fetch 2 0.03 0.13 1251 1254 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.13 1251 1255 0 1
misses in library cache during parse: 1
optimizer mode: all_rows
parsing user id: 91
number of plan statistics captured: 1
rows (1st) rows (avg) rows (max) row source operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 sort aggregate (cr=1254 pr=1251 pw=0 time=137240 us)
87545 87545 87545 table access full t (cr=1254 pr=1251 pw=0 time=126248 us cost=349 size=0 card=94869)
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
enq: ko - fast object checkpoint 1 0.00 0.00
direct path read 12 0.01 0.08
sql*net message from client 2 25.22 25.22
********************************************************************************
elapsed times include waiting on following events:
event waited on times max. wait total waited
---------------------------------------- waited ---------- ------------
db file sequential read 8 0.01 0.05
db file scattered read 47 0.05 0.28
3 user sql statements in session.
1 internal sql statements in session.
4 sql statements in session.
********************************************************************************
trace file: test_ora_6737.trc
end