10046事件主要用來跟蹤sql的執行,提供的資訊比SQL_TRACE多,對SQL_TRACE是個補充
設定trace檔案的辨別,友善查找生成的trace檔案:
HR@orcl>ALTER SESSION SET tracefile_identifier='10046';`
Session altered.
開啟10046跟蹤事件:
HR@orcl>ALTER SESSION SET EVENTS '10046 trace name context forever,level 12';
Session altered.
執行需要跟蹤的sql:
HR@orcl>DELETE FROM departments WHERE department_id =0;
1 row deleted.
HR@orcl>commit;
Commit complete.
關閉10046跟蹤事件:
HR@orcl>ALTER SESSION SET EVENTS '10046 trace name context off';
Session altered.
HR@orcl>
檢視trace檔案的存放目錄
HR@orcl>select name, value from v$parameter where name = 'user_dump_dest';
NAME VALUE
------------------------------ --------------------------------------------------
user_dump_dest d:\app\chujf\diag\rdbms\orcl\orcl\trace
定位生成的trace檔案,檔案命中有開始定義的辨別符
10046
:
HR@orcl>col tracefile format a80
HR@orcl>set line 500
HR@orcl>SELECT DISTINCT vm.sid,vp.pid,vp.tracefile
2 FROM v$mystat vm,v$session vs,v$process vp
3 WHERE vm.SID=vs.SID AND vs.PADDR = vp.addr;
SID PID TRACEFILE
---------- ---------- --------------------------------------------------------------------------------
173 34 d:\app\chujf\diag\rdbms\orcl\orcl\trace\orcl_ora_40940_10046.trc
HR@orcl>
使用tkprof工具将可讀性較差的trace檔案轉換成可讀性較好的
C:\Users\Chujf>cd D:\app\Chujf\diag\rdbms\orcl\orcl\trace
C:\Users\Chujf>d:
D:\app\Chujf\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_40940_10046.trc orcl_ora_40940_10046.sql sys=no
TKPROF: Release 11.2.0.1.0 - Development on Tue Jan 29 21:38:37 2019
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
D:\app\Chujf\diag\rdbms\orcl\orcl\trace>
在trace目錄生成的檔案orcl_ora_40940_10046.sql内容如下(注釋為說明):
TKPROF: Release 11.2.0.1.0 - Development on Tue Jan 29 21:38:37 2019
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: orcl_ora_40940_10046.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed --執行調用的次數
cpu = cpu time in seconds executing --以秒為機關的cpu時間
elapsed = elapsed time in seconds executing --以秒為機關的調用(cpu+等待)時間
disk = number of physical reads of buffers from disk --從磁盤到緩沖區實體讀的數量(資料塊)
query = number of buffers gotten for consistent read --consistent模式下查詢burrer數(select 一緻讀)
current = number of buffers gotten in current mode (usually for update) --current模式查詢buffer數(dml 即時讀)
rows = number of rows processed by the fetch or execute call --被fetch(select)或execute(dml)調用處理的行數
********************************************************************************
--delete語句部分
SQL ID: asxu4rnys9284
Plan Hash: 2526212926
DELETE FROM departments
WHERE
department_id =0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.08 0 41 0 0
Execute 1 0.00 0.01 0 2 11 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.04 0.10 0 43 11 1
/*
Parse:解析(找sqlid;檢查文法、對象、權限;鎖對象;建立和儲存執行計劃)
Execute:執行(select(确認選中的行) dml(執行更改資料的過程))
Fetch:取出(select(傳回行到使用者程序)dml(沒有操作,隻是傳回執行結果))
*/
Misses in library cache during parse: 1 --解析過程在庫緩存中找不到計劃(導緻硬解析的次數)
--Misses in library cache during execute 執行計劃沒有命中 和 計劃在庫緩存中失效(導緻的硬解析次數) 執行調用時沒有硬解析,無此行
Optimizer mode: ALL_ROWS --優化器模式,對應CBO基于成本的優化器;需要統計資料支援,否則自動采樣;另有參數RULE(RBO)等
Parsing user id: 85 --解析使用者id 在資料字典all_users有資訊
Rows Row Source Operation --行源操作:每個行級操作傳回的行數和額外行源資訊,如實體讀寫
------- ---------------------------------------------------
0 DELETE DEPARTMENTS (cr=2 pr=0 pw=0 time=0 us)
1 INDEX UNIQUE SCAN DEPT_ID_PK (cr=1 pr=0 pw=0 time=0 us cost=0 size=10 card=1)(object id 73944)
/*
cr specifies consistent reads performed by the row source(行源操作執行邏輯一緻讀塊數)
pr specifies physical reads performed by the row source(行源操作執行實體讀塊數)
pw specifies physical writes performed by the row source(行源操作執行實體寫塊數)
time specifies time in microseconds(以微秒為機關的估計運作時間)
cost (CBO執行計劃計算開銷)
size (預估傳回的資料量,位元組為機關)
card (預估被處理的行數)
object id (對象id,可從資料字典user_objects找詳細資訊)
*/
Elapsed times include waiting on following events: --總時間包括等待以下事件
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 5.25 5.25
********************************************************************************
--------------------------------------------commit語句部分
SQL ID: 23wm3kz7rps5y
Plan Hash: 0
commit
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.05 0 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.05 0 0 1 0
Misses in library cache during parse: 0
Parsing user id: 85
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file sync 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 338.32 338.32
********************************************************************************
------------------------------------------關閉跟蹤事件語句部分
SQL ID: 0kjg1c2g4gdcr
Plan Hash: 0
ALTER SESSION SET EVENTS '10046 trace name context off'
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 85
********************************************************************************
---------------------------------------tkprof 對所有非遞歸語句的總結
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.04 0.08 0 41 0 0
Execute 3 0.00 0.06 0 2 12 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.04 0.15 0 43 12 1
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 338.32 491.49
log file sync 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 34 0.03 0.02 0 0 0 0
Execute 152 0.09 0.13 0 3 1 1
Fetch 303 0.01 0.00 0 593 0 462
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 489 0.14 0.17 0 596 1 463
Misses in library cache during parse: 24
Misses in library cache during execute: 23
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
3 user SQL statements in session.
152 internal SQL statements in session.
155 SQL statements in session.
********************************************************************************
Trace file: orcl_ora_40940_10046.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
152 internal SQL statements in trace file.
155 SQL statements in trace file.
27 unique SQL statements in trace file.
2803 lines in trace file.
343 elapsed seconds in trace file.
通過sql_id找sql語句:
HR@orcl>select sql_text from v$sqlarea where sql_id = 'asxu4rnys9284';
SQL_TEXT
----------------------------------------------------------------------------------------------------
DELETE FROM departments WHERE department_id =0
原始的trace檔案
orcl_ora_40940_10046.trc
内容如下:
Trace file d:\app\chujf\diag\rdbms\orcl\orcl\trace\orcl_ora_40940_10046.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1
CPU : 4 - type 8664, 2 Physical Cores
Process Affinity : 0x0x0000000000000000
Memory (Avail/Total): Ph:1586M/7644M, Ph+PgF:5301M/15286M
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 34
Windows thread id: 40940, image: ORACLE.EXE (SHAD)
*** 2019-01-29 20:50:19.154
*** SESSION ID:(173.45743) 2019-01-29 20:50:19.154
*** CLIENT ID:() 2019-01-29 20:50:19.154
*** SERVICE NAME:(ORCL) 2019-01-29 20:50:19.154
*** MODULE NAME:(SQL*Plus) 2019-01-29 20:50:19.154
*** ACTION NAME:() 2019-01-29 20:50:19.154
/*
*/
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=7364574083893
*** 2019-01-29 20:52:47.072
WAIT #2: nam='SQL*Net message from client' ela= 147913334 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=7364722021205
CLOSE #2:c=0,e=24,dep=0,type=1,tim=7364722021575
=====================
PARSING IN CURSOR #3 len=789 dep=1 uid=0 oct=3 lid=0 tim=7364722025968 hv=3159716790 ad='7ffbc91aac8' sqlid='7ng34ruy5awxq'
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
END OF STMT
PARSE #3:c=15600,e=3322,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=7364722025966
BINDS #3:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2c5e9168 bln=22 avl=04 flg=05
value=73943
Bind#1
No oacdef for this bind.
EXEC #3:c=0,e=59345,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=2542797530,tim=7364722085832
FETCH #3:c=0,e=1216,p=0,cr=9,cu=0,mis=0,r=1,dep=1,og=4,plh=2542797530,tim=7364722087179