Oracle 10046 trace檔案分析

標籤：

產生10046 trace檔案：

SQL> create table t10046 as select * from dba_objects;Table created.SQL> select file_id,block_id,blocks from dba_extents where segment_name=‘T10046‘;   FILE_ID   BLOCK_ID     BLOCKS---------- ---------- ----------         1      94664          8         1      94672          8         1      94680          8         1      94688          8         1      94696          8         1      94704          8         1      94712          8         1      94896          8         1      94904          8         1      94912          8         1      94920          8         1      94928          8         1      94936          8         1      94944          8         1      94952          8         1      94960          8         1      95872        128         1      96000        128         1      96128        128         1      96256        128         1      96384        128         1      96512        128         1      96640        128         1      96768        128         1      96896        12825 rows selected.SQL> alter session set events ‘10046 trace name context forever,level 12‘;Session altered.#沒有建立索引，會走全表掃描SQL> select count(*) from t10046;  COUNT(*)----------     86956SQL> alter session set events ‘10046 trace name context off‘;

 

10046 trace 檔案的內容：

=====================PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad=‘7bf41070‘ sqlid=‘awzvq6b3dapqt‘select count(*) from t10046END OF STMTPARSE #140231913930616:c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403EXEC #140231913930616:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292551WAIT #140231913930616: nam=‘SQL*Net message to client‘ ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1458364346292607WAIT #140231913930616: nam=‘enq: KO - fast object checkpoint‘ ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=1458364346296691WAIT #140231913930616: nam=‘direct path read‘ ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284WAIT #140231913930616: nam=‘direct path read‘ ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150WAIT #140231913930616: nam=‘direct path read‘ ela= 912 file number=1 first dba=95872 block cnt=128 obj#=88635 tim=1458364346300730WAIT #140231913930616: nam=‘direct path read‘ ela= 386 file number=1 first dba=96000 block cnt=128 obj#=88635 tim=1458364346301893WAIT #140231913930616: nam=‘direct path read‘ ela= 299 file number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928WAIT #140231913930616: nam=‘direct path read‘ ela= 371 file number=1 first dba=96256 block cnt=128 obj#=88635 tim=1458364346304307WAIT #140231913930616: nam=‘direct path read‘ ela= 236 file number=1 first dba=96384 block cnt=128 obj#=88635 tim=1458364346305513WAIT #140231913930616: nam=‘direct path read‘ ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513WAIT #140231913930616: nam=‘direct path read‘ ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527WAIT #140231913930616: nam=‘direct path read‘ ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125WAIT #140231913930616: nam=‘direct path read‘ ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304FETCH #140231913930616:c=14998,e=19124,p=1240,cr=1243,cu=0,mis=0,r=1,dep=0,og=1,plh=2130400753,tim=1458364346311758STAT #140231913930616 id=1 cnt=1 pid=0 pos=1 obj=0 op=‘SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us)‘STAT #140231913930616 id=2 cnt=86956 pid=1 pos=1 obj=88635 op=‘TABLE ACCESS FULL T10046 (cr=1243 pr=1240 pw=0 time=24549 us cost=338 size=0 card=70030)‘WAIT #140231913930616: nam=‘SQL*Net message from client‘ ela= 225 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=1458364346312363FETCH #140231913930616:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2130400753,tim=1458364346312405WAIT #140231913930616: nam=‘SQL*Net message to client‘ ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=1458364346312426*** 2016-03-19 13:12:37.876WAIT #140231913930616: nam=‘SQL*Net message from client‘ ela= 11563756 driver id=1650815232 #bytes=1 p3=0 obj#=88635 tim=1458364357876195CLOSE #140231913930616:c=0,e=10,dep=0,type=0,tim=1458364357876316=====================

 

10046 trace 檔案內容分析：

1.資料庫調用
含3個子分類：解析，執行和擷取
這3個分類與通過調用DBMS_SQL的子常式DBMS_SQL.PARSE,DBMS_SQL.EXECUTE,DBMS_SQL.FETCH_ROWS來跑SQL的步調相一致
解析在追蹤檔案中通常通過兩個相鄰的條目表示：第一個是PARSING IN CURSOR,第二個是PARSE。如下所示：

PARSING IN CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad=‘7bf41070‘ sqlid=‘awzvq6b3dapqt‘select count(*) from t10046END OF STMTPARSE #140231913930616:c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403

(1)PARSING IN CURSOR各項的具體含義

參數	說明
len	表示sql語句文本位元組長度 　　#"select count(*) from t10046"位元組長度為27
dep	遞迴調用深度　　#本次調用深度為0
uid	解析使用者識別碼，對應於all_users.user_id以及v$sql.parsing_user_id　　#本次是以sys使用者執行的，故uid=0
oct	oracle命令類型，對應於v$sql.command_type以及v$session.command　　#select對應類型是3
lid	解析模式標識符，對應於all_users.user_id以及v$sql.parsing_schema_id，可能與uid不同
tim	微秒單位時間戳記，在關聯的parse條目中通常比tim的值早一點
hv	雜湊值，對應於v$sql.hash_value
ad	address，對應於v$sql.address
sqlid	sql id，對應與v$sql.sql_id

 

 

 

 

 

 

 

 

 

 

(2)PARSE各項的具體含義

參數	說明
c	cpu開銷
e	已耗用時間
p	物理讀
cr	一致讀
cu	當前處理的資料區塊
mis	遊標丟失，0表示軟解析；1表示硬解析
r	被處理的資料行
dep	遞迴調用深度
og	最佳化目標。1:all_rows,2:first_rows,3:rule,4:choose。oracle 10g 後預設是all_rows
plh	執行計畫的hash值。對應於v$sql_plan.plan_hash_value,v$sql_plan_statistics_all.plan_hash_value以及v$sqlstats.plan_hash_value
tim	時間戳記，單位為微秒

 

 

 

 

 

 

 

 

 

 

 

 

2.執行計畫，統計資訊與STAT條目格式

一組STAT條目的每一行代表了形成語句結果的行源。所謂的行源，指從索引或表中檢索的資料或者多表串連的中間結果(因為必須先進行兩表串連)。
10g以後，STAT條目僅在TIMED_STATISTICS=TRUE,並且SQL_TRACE=TRUE時才被寫入。請注意，若STATISTICS_LEVEL=BASIC(預設為TYPICAL)時會隱式設定TIMED_STATISTICS=FASLE。

STAT #140231913930616 id=1 cnt=1 pid=0 pos=1 obj=0 op=‘SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us)‘STAT #140231913930616 id=2 cnt=86956 pid=1 pos=1 obj=88635 op=‘TABLE ACCESS FULL T10046 (cr=1243 pr=1240 pw=0 time=24549 us cost=338 size=0 card=70030)‘

(1)stat說明

參數	說明
id	執行計畫中指示行資料來源順序的標識符，通常一個執行計畫的第一條stat行的id=1
cnt	被處理的行數
pid	父標識符，通常一個執行計畫的第一條stat行的pid=0。通過比一個計劃的父步驟高一個層級縮排的依賴步驟，tkprof和esqltrcprof使用id以及pid產生適當縮排的執行計畫
pos	父步驟中的一個步驟的位置
obj	物件識別碼，對應於all_objects.object_id和v$sql_plan.object#
op	執行的行資料來源操作，比如表訪問、索引掃描、排序、聯合等，對應於v$sql_plan.operation。在10g中，在行資料來源資訊後面op的括弧中包含實際語句執行指標
cr	一致性讀
pr	物理讀
pw	物理寫
time	估計的已耗用時間，單位為微秒
cost	cbo計算的執行計畫成本
size	估計的數量，單位為位元組
card	估計的基數，即被處理的行數

 

 

 

 

 

 

 

 

 

3.等待事件和WAIT條目格式

WAIT #140231913930616: nam=‘SQL*Net message to client‘ ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1458364346292607WAIT #140231913930616: nam=‘enq: KO - fast object checkpoint‘ ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=1458364346296691WAIT #140231913930616: nam=‘direct path read‘ ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284WAIT #140231913930616: nam=‘direct path read‘ ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150WAIT #140231913930616: nam=‘direct path read‘ ela= 912 file number=1 first dba=95872 block cnt=128 obj#=88635 tim=1458364346300730WAIT #140231913930616: nam=‘direct path read‘ ela= 386 file number=1 first dba=96000 block cnt=128 obj#=88635 tim=1458364346301893WAIT #140231913930616: nam=‘direct path read‘ ela= 299 file number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928WAIT #140231913930616: nam=‘direct path read‘ ela= 371 file number=1 first dba=96256 block cnt=128 obj#=88635 tim=1458364346304307WAIT #140231913930616: nam=‘direct path read‘ ela= 236 file number=1 first dba=96384 block cnt=128 obj#=88635 tim=1458364346305513WAIT #140231913930616: nam=‘direct path read‘ ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513WAIT #140231913930616: nam=‘direct path read‘ ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527WAIT #140231913930616: nam=‘direct path read‘ ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125WAIT #140231913930616: nam=‘direct path read‘ ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304

參數	說明
ela	已耗用時間，單位為微秒
p1	等待事件的第一個參數。對應於v$session_wait.p1
p2	等待事件的第二個參數。對應於v$session_wait.p2
p3	等待事件的第三個參數。對應於v$session_wait.p3
tim	時間戳記
file#	絕對檔案編號
block#	資料區塊號
blocks	資料區塊數量
obj#	對象編號，就是object_id
nam	等待事件的名稱

 

 

 

 

 

 

 

 

 

 

 

參考：http://blog.itpub.net/29320885/viewspace-1223962/

Oracle 10046 trace檔案分析