天天看點

學習ORACLE-10046跟蹤事件相關

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
           

繼續閱讀