10046事件詳解

yepkeepmoving發表於2016-11-01
事件

10046事件詳解

 

一、      10046事件概述

10046是一個Oracle的內部事件(event)，透過設定這個事件可以得到Oracle內部執行系統解析、呼叫、等待、繫結變數等詳細的trace資訊，即幫助我們解析一條/多條SQL、PL/SQL語句的執行狀態，這些狀態包括：Parse/Fetch/Execute三個階段中遇到的等待事件、消耗的物理和邏輯讀、CPU時間、執行計劃等。它不僅為我們揭示了一條、多條SQL的執行情況，同時還能幫我們分析一些DDL維護命令的內部工作原理，RMAN、Data Pump Expdp/impdp等工具緩慢問題。對於SQL效能最佳化、分析系統的效能有著非常重要的作用。

 

二、      10046執行級別

 

 

Level 0

停用SQL跟蹤，相當於SQL_TRACE=FALSE，無任何輸出

Level 1

標準SQL跟蹤，相當於SQL_TRACE=TRUE;

輸出 …APPNAME（應用程式名）,PARSING IN CURSOR,PARSE ERROR（SQL解析）,EXEC（執行）,FETCH（獲取資料）,UNMAP,SORT UNMAP（排序，臨時段）,ERROR,STAT（執行計劃）,XCTEND（事務）等行

Level 4

在level 1的基礎上增加繫結變數的資訊，即好含1資訊+binding events

Level 8

在level 1的基礎上增加等待事件的資訊，即包含1資訊+waiting events

Level 12

在level 1的基礎上增加繫結變數和等待事件的資訊，即包含1、4、8的資訊

 

三、      10046 trace檔案路徑

從11gR1開始，Oracle引入了新的診斷結構，以引數DIAGNOSTIC_DEST控制存放trace檔案與core檔案的路徑。可以用以下命令，獲取DIAGNOSTIC_DEST的位置：

    SQL> show parameter diagnostic_dest;

    11gR1以前,如果是使用者程式，10046 trace檔案會被生成在user_dump_dest下,如果是後臺程式，trace檔案會被生成在background_dump_dest下,下面的命令可以顯示user_dump_dest:

    SQL> show parameter user_dump_dest ;

    SQL> show parameter background_dump_dest;

 

注意：透過設定tracefile_identifier即alter session set tracefile_identifier='mytrace' ，透過這個設定可以幫助我們更容易的找到生成的trace檔案。

 

擴充套件：

（1）可以透過SQL獲取當前session的跟蹤檔案位置：

select

a.value || '/' || b.instance_name || '_ora_' || c.spid || '.trc' trace_file

from

(select value from v$parameter where name= 'user_dump_dest') a,

(select instance_name from v$instance) b,

(select spid from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat))) c;

或者

select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));

 

 

四、      10046 trace相關引數

 

1.          timed_statistics

timed_statistics這個引數決定了是否收集與時間相關的統計資訊，如果這個引數為FALSE的話，那麼SQL Trace的結果基本沒有多大的用處，預設情況下這個引數設定為TRUE。

show parameter timed_statistics ;

ALTER SESSION SET timed_statistics=true ;

2.          max_dump_file_size

max_dump_file_size這個引數指定dump檔案的大小，也就是決定是否限制SQL Trace檔案的大小，在一個很忙的系統上面做SQL Trace的話可能會生成很多的資訊，因此最好在會話級別將這個引數設定成unlimited。

show parameter max_dump_file_size;

ALTER SESSION SET max_dump_file_size=unlimited ;

3.          tracefile_identifier

tracefile_identifier這個引數給Trace檔案設定識別字串，是個非常有用的引數，設定一個易讀的字串能更快的找到Trace檔案。

show parameter  tracefile_identifier;

ALTER SESSION SET tracefile_identifier=’my_trace_session’;

 

 

4.          diagnostic_dest

diagnostic_dest這個引數11g新增的，用於控制存放trace檔案與core檔案的路徑，預設是$ORACLE_BASE目錄。

show parameter diagnostic_dest; 命令用於檢視其目錄

 

5.          user_dump_dest

user_dump_dest引數指定使用者程式trace檔案目錄。

show parameter user_dump_dest ; 命令可以產看其目錄

alter system set user_dump_dest ='/U01/app/oracle/diag/rdbms/masterdb/masterdb/trace' scope=both; 命令用於更改其目錄

6.          background_dump_dest

background_dump_dest引數用於後臺程式產生的trace檔案儲存目錄下。

show parameter background_dump_dest ; 命令可以檢視其目錄

alter system set

background_dump_dest='/U01/app/oracle/diag/rdbms/masterdb/masterdb/trace' scope=both; 命令用於更改其目錄

 

注意：如果想要設定其他程式的上述引數，需要透過DBMS包設定，但tracefile_identifier是無法在別的會話中修改。

具體設定命令為：

SYS.DBMS_SYSTEM.SET_BOOL_PARAM_IN_SESSION(:sid, :serial,'timed_statistics', true) ;

SYS.DBMS_SYSTEM.SET_INT_PARAM_IN_SESSION(:sid, :serial,'max_dump_file_size', 2147483647) ;

 

五、      10046 trace設定方法

 

1.          10046事件會話級別

 

這種方法適用於SQL語句可以在新的session建立後再執行。

語法：

alter session set events '[eventnumber|immediate] trace name eventname [forever] [, level levelnumber] : .......'

1.1 開啟session sql trace

    alter session set tracefile_identifier='10046';

    alter session set timed_statistics = true;      --預設是true

    alter session set statistics_level=all;               --例項級別設定需要注意，會消耗大量的CPU

    alter session set max_dump_file_size = unlimited;       --預設是unlimited

    alter session set events '10046 trace name context forever,level 12'; --常用的級別是12

 

set serveroutput off;

alter session set tracefile_identifier='10046';

alter session set timed_statistics = true;

alter session set statistics_level=all;     

alter session set max_dump_file_size = unlimited;

alter session set events '10046 trace name context forever,level 12';

 

1.2 執行要trace的SQL

select * from scott.dept;

 

1.3 關閉session sql trace

alter session set events '10046 trace name context off';

 

或者直接退出session

exit

1.4 檢視session sql trace路徑

select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));

或者

select

a.value || '/' || b.instance_name || '_ora_' || c.spid || '.trc' trace_file

from

(select value from v$parameter where name= 'user_dump_dest') a,

(select instance_name from v$instance) b,

(select spid from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat))) c;

 

或者

show parameter user_dump_dest ;

 

1.5 分析session sql trace

（1）      直接檢視

 

more /U01/app/oracle/diag/rdbms/masterdb/masterdb/trace/masterdb_ora_20596_10046.trc  

 

=====================

PARSING IN CURSOR #47019101509648 len=24 dep=0 uid=0 oct=3 lid=0 tim=1477908470545403 hv=911793802 ad='74c73648' sqlid='f6hhpzwv5jrna'

select * from scott.dept

END OF STMT

PARSE #47019101509648:c=33995,e=65940,p=14,cr=62,cu=0,mis=1,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545401

EXEC #47019101509648:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545479

WAIT #47019101509648: nam='SQL*Net message to client' ela= 14 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1477908470545527

WAIT #47019101509648: nam='Disk file operations I/O' ela= 115 FileOperation=2 fileno=4 filetype=2 obj#=87106 tim=1477908470545730

WAIT #47019101509648: nam='db file sequential read' ela= 24 file#=4 block#=130 blocks=1 obj#=87106 tim=1477908470545780

WAIT #47019101509648: nam='db file scattered read' ela= 60 file#=4 block#=131 blocks=5 obj#=87106 tim=1477908470545972

FETCH #47019101509648:c=0,e=510,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1477908470546076

WAIT #47019101509648: nam='SQL*Net message from client' ela= 644 driver id=1650815232 #bytes=1 p3=0 obj#=87106 tim=1477908470546764

WAIT #47019101509648: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=87106 tim=1477908470546816

FETCH #47019101509648:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1477908470546841

STAT #47019101509648 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=6 pw=0 time=498 us cost=3 size=80 card=4)'

 

*** 2016-10-31 18:08:35.900

WAIT #47019101509648: nam='SQL*Net message from client' ela= 45353246 driver id=1650815232 #bytes=1 p3=0 obj#=87106 tim=1477908515900182

CLOSE #47019101509648:c=0,e=13,dep=0,type=0,tim=1477908515900388

=====================

 

 

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

 

其中下面含義解釋：

（1）第一部分整體trace概覽含義

PARSING IN CURSOR #47019101509648 len=24 dep=0 uid=0 oct=3 lid=0 tim=1477908470545403 hv=911793802 ad='74c73648' sqlid='f6hhpzwv5jrna'

 

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

 

（2）第二部分SQL具體執行過程以及CPU等效能指標含義

PARSE #47019101509648:c=33995,e=65940,p=14,cr=62,cu=0,mis=1,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545401

EXEC #47019101509648:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=1477908470545479

FETCH #47019101509648:c=0,e=510,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=1477908470546076

FETCH #47019101509648:c=0,e=36,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=1477908470546841

 

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

 

 

 

（3）第三部分執行過程中發生的等待含義

WAIT #47019101509648: nam='SQL*Net message from client' ela= 644 driver id=1650815232 #bytes=1 p3=0 obj#=87106 tim=1477908470546764

 

nam

 an event that we waited for 等待事件

ela

 此操作消耗的時間

p3

 block 塊號

trm

 timestamp 時間戳

 

（4）第四部分遊標執行計劃含義

 

STAT #47019101509648 id=1 cnt=4 pid=0 pos=1 obj=87106 op='TABLE ACCESS FULL DEPT (cr=7 pr=6 pw=0 time=498 us cost=3 size=80 card=4)'

 

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

上述邏輯讀為7，物理讀為6，消耗時間為498us，消耗3，返回記錄大小80B，記錄數4

 

 

（2）       tkprof檢視

tkprof /U01/app/oracle/diag/rdbms/masterdb/masterdb/trace/masterdb_ora_20596_10046.trc   10046_tkprof.trc

 

TKPROF: Release 11.2.0.4.0 - Development on Mon Oct 31 18:41:56 2016

 

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

 

Trace file: /U01/app/oracle/diag/rdbms/masterdb/masterdb/trace/masterdb_ora_20687_10046.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

********************************************************************************

 

********************************************************************************

 

SQL ID: f6hhpzwv5jrna Plan Hash: 3383998547

 

select *

from

 scott.dept

 

 

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.03       0.06         14         62          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch        2      0.00       0.00          6          7          0           4

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total        4      0.03       0.06         20         69          0           4

 

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: SYS

Number of plan statistics captured: 1

 

Rows (1st) Rows (avg) Rows (max)  Row Source Operation

---------- ---------- ----------  ---------------------------------------------------

         4          4          4  TABLE ACCESS FULL DEPT (cr=7 pr=6 pw=0 time=498 us cost=3 size=80 card=4)

 

 

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

  Disk file operations I/O                        1        0.00          0.00

  db file sequential read                         1        0.00          0.00

  db file scattered read                          1        0.00          0.00

  SQL*Net message from client                     2       45.35         45.35

********************************************************************************

其中有Misses in library cache during parse ：1  則表明解析的時候庫快取丟失遊標,  也就是說發生了一次硬解析。

 

http://blog.itpub.net/27067062/viewspace-2127398/

 

 

注意：

如果session沒有被徹底地關閉並且跟蹤被停止了，某些重要的trace資訊的可能會丟失。這裡我們將"statistics_level"設定為all，這是因為有可能這個引數在系統級不是預設值"TYPICAL"（比如 BASIC）。為了收集效能相關問題的資訊我們需要開啟某個級別的statistics。我們推薦在 session 級將這個引數設定成 ALL 以便於收集更多的資訊，儘管這不是必須的。

 

2.          10046事件程式級別跟蹤

 

如果需要跟蹤一個已經存在session，可以用 oradebug連線到session上，併發起10046 trace。也可以透過DBMS_SYSTEM.SET_EV系統包來實現。

 

2.1 Oradebug分析其他使用者程式trace

 

查詢要跟蹤的session資訊：

SQL> select sid,serial#,username from v$session where username is not null;

 

       SID    SERIAL# USERNAME

---------- ---------- ------------------------------

        18        663 SYS

       135      17081 SYS

       197      38741 SCOTT

       205       1491 SCOTT

 

根據session資訊找到對應的程式號SPID：

select p.PID,p.SPID,s.SID from v$process p,v$session s

     where s.paddr = p.addr and s.sid = &SESSION_ID ;

Enter value for session_id: 205

       PID SPID                            SID

---------- ------------------------ ----------

        39 25620                           205

 

 

開啟程式追蹤：

SQL> oradebug setospid 25620

Oracle pid: 39, Unix process pid: 25620, image: oracle@node4 (TNS V1-V3)

SQL> oradebug unlimit

Statement processed.

SQL> oradebug event 10046 trace name context forever,level 12

Statement processed.

 

###也可以透過oradebug使用 'setorapid'命令連線到一個session，即oradebug setorapid 39

 

 

 

執行查詢：

SQL> select * from dept where deptno=10;

 

    DEPTNO DNAME          LOC

---------- -------------- -------------

        10 ACCOUNTING     NEW YORK

 

關閉oradebug跟蹤：

 

oradebug event 10046 trace name context off

 

檢視追蹤檔案並分析：

 

SQL>  select tracefile from v$process where addr=(select paddr from v$session where sid=205);

 

TRACEFILE

--------------------------------------------------------------------------------

/U01/app/oracle/diag/rdbms/masterdb/masterdb/trace/masterdb_ora_25620.trc

 

可以透過直接檢視或者tkprof分析上述trace檔案，原理同上。

 

2.2 DBMS_SYSTEM.SET_EV分期其他使用者程式trace

 

語法格式：

exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#, SQL_TRACE) ;

         sid:會話sid

         serial#:會話serial#

         sql_trace:true or false

exec  dbms_system.SET_EV(si,se,ev,le,nm) ;

         si：會話sid,來自v$session

         se:會話serial#,來自v$session

         ev:跟蹤事件Num,如10046

         le:跟蹤事件級別，如1,2,4,8,12

         nm:會話使用者名稱，來自v$session

 

注意：如果想要設定其他程式的上述引數，需要透過DBMS包設定，但tracefile_identifier是無法在別的會話中修改。

具體設定命令為：

SYS.DBMS_SYSTEM.SET_BOOL_PARAM_IN_SESSION(:sid, :serial,'timed_statistics', true) ;

SYS.DBMS_SYSTEM.SET_INT_PARAM_IN_SESSION(:sid, :serial,'max_dump_file_size', 2147483647) ;

 

 

查詢獲得需要跟蹤的session資訊:

 

SQL>  select sid,serial#,username from v$session where username is not null;

 

       SID    SERIAL# USERNAME

---------- ---------- ------------------------------

       135      17081 SYS

       197      38741 SCOTT

 

執行現有會話程式跟蹤:

 

 

SQL> exec dbms_system.SET_EV(197,38741,10046,12,'SCOTT') ;

 

PL/SQL procedure successfully completed.

 

SQL> exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(197,38741,true) ;

 

PL/SQL procedure successfully completed.

 

 

執行查詢操作：

 

SQL> select * from dept where deptno<=30;

 

    DEPTNO DNAME          LOC

---------- -------------- -------------

        10 ACCOUNTING     NEW YORK

        20 RESEARCH       DALLAS

        30 SALES          CHICAGO

 

結束會話跟蹤：

 

SQL> exec dbms_system.SET_EV(197,38741,10046,0,'SCOTT') ;

 

PL/SQL procedure successfully completed.

 

SQL> exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(197,38741,false) ;

 

PL/SQL procedure successfully completed.

 

 

跟蹤檔案分析：

 

SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=197);

 

TRACEFILE

--------------------------------------------------------------------------------

/U01/app/oracle/diag/rdbms/masterdb/masterdb/trace/masterdb_ora_24413.trc

 

或者

select pa.value || '/' || i.instance_name||'_ora_'||ps.spid||'.trc'

from (select  value from v$parameter where name= 'user_dump_dest') pa,

     (select s.sid sid,p.spid spid from v$session s,v$process p where s.PADDR=p.ADDR and s.sid=&&sid) ps,

     (select instance_name from v$instance) i;

 

透過直接檢視或者tkprof分析，原理同上。

 

 

3.          10046事件例項級別跟蹤

 

在例項層設定跟蹤需要非常小心，這是因為整體效能會由於所有session都被跟蹤而受到影響，這個設定將會跟蹤在這個引數設定“以後”建立的每個session。已經存在的session不會被跟蹤，系統層的10046跟蹤適用於當我們知道問題session會出現，但是不能預先識別它的時候，在這種情況下，可以開啟系統層跟蹤一小段時間，當問題被重現以後立即將其關閉，然後從已經生成的trace中查詢需要的資訊，用以下命令開啟系統層的跟蹤：

 

    alter system set events '10046 trace name context forever,level 12'

 

用以下命令關閉在所有session中的10046跟蹤：

 

    alter system set events '10046 trace name context off';

 

4.          10046初始化引數例項級別跟蹤

 

設定以下引數並重新啟動例項後，例項上所有的session都會開啟跟蹤。

event="10046 trace name context forever,level 12"

如果要關閉可以透過移除這個引數並且重啟例項，或者使用下面的alter system命令可以關閉跟蹤。

    alter system set events '10046 trace name context off';

5.          10046事件logon trigger跟蹤

 

有的時候當需要跟蹤某個特定使用者的操作時，可以使用logon trigger來開啟跟蹤

 

   CREATE OR REPLACE TRIGGER SYS.set_trace

   AFTER LOGON ON DATABASE

   WHEN (USER like '&USERNAME')

   DECLARE

   lcommand varchar(200);

   BEGIN

   EXECUTE IMMEDIATE 'alter session set tracefile_identifier=''From_Trigger''';

   EXECUTE IMMEDIATE 'alter session set statistics_level=ALL';

   EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';

   EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12''';

   END set_trace;

   /

 

   需要注意的事，為了能開啟跟蹤session, 執行trigger的使用者需要被顯式地授予'alter session'許可權

 

   grant alter session to user_db

 

6.          10046事件DBMS Monitor跟蹤

 

 

六、      參考文件：

1、tkprof分析trace檔案

http://www.cnblogs.com/luoyx/archive/2012/05/19/2508890.html

 

2、10046 trace開啟方法

http://blog.sina.com.cn/s/blog_61cd89f60102edlx.html

 

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

相關文章