使用10046 ,10053 並讀懂 trace 檔案

li__hl8888發表於2016-05-18

檢視 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 檔案的完整路徑.

[sql] view plain copy print?

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
background_dump_dest string g:\app\davidd\diag\rdbms\david
\david\trace

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
background_dump_dest                 string      g:\app\davidd\diag\rdbms\david
                                                 \david\trace

剛剛提到的 oradebug 啟用跟蹤 10046 事件, 我想大部分 dba 都會使用. oradebug 是個功能強大非常好用的工具, 使用 oradebug help 將會看到它的功能很多

[sql] view plain copy print?

SQL> oradebug help
HELP [command] Describe one or all commands
SETMYPID Debug current process
SETOSPID Set OS pid of process to debug
SETORAPID ['force'] Set Oracle pid of process to debug
SETORAPNAME Set Oracle process name to debug
SHORT_STACK Get abridged OS stack
CURRENT_SQL Get current SQL
DUMP [addr] Invoke named dump
DUMPSGA [bytes] Dump fixed SGA
DUMPLIST Print a list of available dumps
EVENT Set trace event in process
SESSION_EVENT Set trace event in session
DUMPVAR <name> [level] Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE <count> Print/dump an address with type info
SETVAR <name> Modify a fixed PGA/SGA/UGA variable
PEEK [level] Print/Dump memory
POKE Modify memory
WAKEUP 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</inst-list | def | > Parallel oradebug command prefix
-R <inst-list | def | all</inst-list | def | > Parallel oradebug prefix (return output
SETINST <instance# .. | all</instance# .. | > Set instance list in double quotes
SGATOFILE Dump SGA to file; dirname in double quotes
DMPCOWSGA Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA 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 Helps translate PCs to names
WATCH <self|exist|all|target> Watch a region of memory </self|exist|
DELETE <local|global|target> watchpoint 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 [arg1] ... [argn] Invoke function with arguments

SQL> oradebug help
HELP           [command]                 		Describe one or all commands
SETMYPID                                 		Debug current process
SETOSPID                          		Set OS pid of process to debug
SETORAPID       ['force']        		Set Oracle pid of process to debug
SETORAPNAME                    		Set Oracle process name to debug
SHORT_STACK                              		Get abridged OS stack
CURRENT_SQL                              		Get current SQL
DUMP             [addr]  		Invoke named dump
DUMPSGA        [bytes]                   		Dump fixed SGA
DUMPLIST                                 		Print a list of available dumps
EVENT                              		Set trace event in process
SESSION_EVENT                      		Set trace event in session
DUMPVAR          [level]  		Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE
		
			   		Print/dump an address with type info
SETVAR             		Modify a fixed PGA/SGA/UGA variable
PEEK             [level]      		Print/Dump memory
POKE                   		Modify memory
WAKEUP                           		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                		Parallel oradebug command prefix
-R                		Parallel oradebug prefix (return output
SETINST              		Set instance list in double quotes
SGATOFILE                  		Dump SGA to file; dirname in double quotes
DMPCOWSGA       		 		Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA                  		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                		Helps translate PCs to names
WATCH
			
				   Watch a region of memory
DELETE          watchpoint     Delete a watchpoint
SHOW            watchpoints        Show  watchpoints
DIRECT_ACCESS   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            [arg1] ... [argn]  		Invoke function with arguments

使用 oradebug 跟蹤 10046 命令如下:

[sql] view plain copy print?

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

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 檔案的內容

[sql] view plain copy print?

<pre name</pre ="code" class="sql"><pre name</pre ="code" class="sql"><pre name</pre ="code" class="sql"><pre name</pre ="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)'

檔案我們可以看出 sql 語句經過了 parse(解析) -> exec(執行) -> fetch(從遊標中獲取資料) 幾個過程, 其中第一句說明了當前跟蹤執行的 sql 語句的概況,比如使用遊標號, sql 語句的長度, 遞迴深度等等基本資訊:

[sql] view plain copy print?

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'

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

接著, 下面的語句說明了 sql 語句具體的執行過程以及每一個步驟消耗 CPU 的時間等效能指標

[sql] view plain copy print?

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

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 時間戳

以及執行過程中的發生的等待事件

[sql] view plain copy print?

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512

nam	an event that we waited for 等待事件
ela	此操作消耗的時間
p3	block 塊號
trm	timestamp 時間戳

最後顯示的是該遊標的執行計劃

[sql] view plain copy print?

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

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

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

例如, 執行步驟 merge join 消耗的邏輯讀為 119, 物理讀為 0, 耗費的時間為 28 us, 成本 cost 193，返回 10 條記錄

使用 tkprof 命令翻譯 trace 檔案

我們也可以使用 tkprof 命令對 trace 檔案進行翻譯，得到一個容易理解的 trace 彙總報表檔案

[sql] view plain copy print?

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.

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 檔案的彙總報表如下：

[sql] view plain copy print?

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.

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 意思是解析的時候庫快取丟失遊標, 也就是說發生了一次硬解析

參考:

//////////////////////////////////////**********10053 event**************/////////////////////////////////////////////









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 語句的長度, 遞迴深度等等基本資訊: 
						
						
							

						
						
							
								
									[sql] view plain copy print? 
								
							
							
								
									PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'   
								
							
						
PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'

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

接著, 下面的語句說明了 sql 語句具體的執行過程以及每一個步驟消耗 CPU 的時間等效能指標

[sql] view plain copy print?

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

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 時間戳

以及執行過程中的發生的等待事件

[sql] view plain copy print?

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512

nam	an event that we waited for 等待事件
ela	此操作消耗的時間
p3	block 塊號
trm	timestamp 時間戳

最後顯示的是該遊標的執行計劃

[sql] view plain copy print?

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

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

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

例如, 執行步驟 merge join 消耗的邏輯讀為 119, 物理讀為 0, 耗費的時間為 28 us, 成本 cost 193，返回 10 條記錄

使用 tkprof 命令翻譯 trace 檔案

我們也可以使用 tkprof 命令對 trace 檔案進行翻譯，得到一個容易理解的 trace 彙總報表檔案

[sql] view plain copy print?

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.

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 檔案的彙總報表如下：

[sql] view plain copy print?

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 意思是解析的時候庫快取丟失遊標, 也就是說發生了一次硬解析

參考:

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8568259/viewspace-2102347/，如需轉載，請註明出處，否則將追究法律責任。

相關文章

讀懂Oracle 10046 SQL TRACE
2013-08-26
OracleSQL
sql_trace、10046、10053、tkprof
2017-07-13
SQL
trace檔案閱讀
2011-03-13
利用10046事件收集SQL的trace檔案
2017-03-17
事件SQL
【效能】解讀10053檔案
2020-04-02
Maclean教你讀Oracle 10046 SQL TRACE
2017-12-23
MacOracleSQL
10046 跟蹤的trace檔案相關解釋
2010-10-29
trace檔案備份控制檔案並執行恢復
2016-11-08
ORACLE TRACE 10046
2014-12-05
Oracle
10046 事件與 10053 事件
2017-04-17
事件
如何使用SQL_TRACE和10046事件
2015-07-23
SQL事件
Oracle 10046 SQL TRACE
2018-12-23
OracleSQL
oracle 11gr2中使用dbms_sqldiag.dump_trace來獲得10053跟蹤檔案
2014-11-27
OracleSQL
SQL TRACE和TKPROF,10046的使用步驟
2011-07-06
SQL
10046 trace詳解(1)
2015-05-20
sql_trace/ 10046 整理
2011-03-13
SQL
sql_trace and 10046事件
2012-11-07
SQL事件
【10053 事件】10053事件的跟蹤檔案解析
2010-10-21
事件
Oracle 使用者Trace 檔案路徑
2009-05-20
Oracle
讀取檔案流並寫入檔案流
2018-07-18
Oracle SQL Trace 和 10046 事件
2013-11-26
OracleSQL事件
Oracle SQL Trace 和10046 事件
2011-07-29
OracleSQL事件
Event 10046 - Enable SQL Statement Trace
2008-01-09
SQL
Oracle跟蹤檔案trace檔案
2016-02-29
Oracle
使用10046 event trace跟蹤全表掃描操作
2007-07-26
oracle trace檔案解析
2006-03-26
Oracle
Swift 下載檔案，並讀取
2015-03-10
Swift
oracle sql trace與10046淺談
2014-02-11
OracleSQL
ZT 自動10046 trace指令碼
2009-02-01
指令碼
How to read Oracle 10046 trace file
2008-01-15
Oracle
如何使用Python讀取文字檔案並回答問題？
2024-02-21
Python
使用SQL_TRACE /10046進行資料庫診斷
2010-12-15
SQL資料庫
trace檔案無法生成
2008-06-14
利用trace重建控制檔案
2013-02-28
使用11G 的ADRCI 清除trace檔案
2012-04-25
java讀取大檔案並處理
2019-02-20
Java
python解壓並讀取檔案
2020-11-23
Python
單個SQL語句的10046 trace
2018-12-19
SQL