10046事件
Oracle的10046事件，可以跟蹤應用程序所執行的SQL語句，并且得到其解析次數.執行次數,CPU使用時間等信息。這對我們分析、定位數據庫性能問題是非常有用的。
10046 event是oracle用于系統性能分析時的一個最重要的事件。當激活這個事件后，將通知oracle kernel追蹤會話的相關即時信息，并寫入到相應trace文件中。
這些有用的信息主要包括sql是如何進行解析，綁定變量的使用情況，會話中發生的等待事件等
10046 event 可分成不同的級別（level），分別追蹤記錄不同程度的有用信息。對于這些不同的級別，應當注意的是向下兼容的，即高一級的trace信息包含低于此級的所有信息。
10046event的追蹤級別大致有：
level 1：跟蹤sql語句，包括解析、執行、提取、提交和回滾等。
level 4：包括變量的詳細信息
level 8：包括等待事件
level 12：包括綁定變量與等待事件
其中，level 1相當于打開了sql_trace
在打開10046時間的SQL Trace之前，要先設置好下面幾個參數。
timed_statistics
這個參數決定了是否收集與時間相關的統計信息，如果這個參數為FALSE的話，那么SQL Trace的結果基本沒有多大的用處，默認情況下這個參數設置為TRUE。
max_dump_file_size
dump文件的大小，也就是決定是否限制SQL Trace文件的大小，在一個很忙的系統上面做SQL Trace的話可能會生成很多的信息，因此最好在會話級別將這個參數設置成unlimited。
tracefile_identifier
給Trace文件設置識別字符串，這是個非常有用的參數，設置一個易讀的字串能更快的找到Trace文件。
要在當前會話修改上述參數很簡單，只要使用下面的命令即可：
ALTER SESSION SET timed_statistics=true
ALTER SESSION SET max_dump_file_size=unlimited
ALTER SESSION SET tracefile_identifier='my_trace_session'
實驗：設置10046事件
alter session set events '10046 trace name context forever ,level 12';
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2;
alter session set events '10046 trace name context off';
當前會話查看生成的trace 文件
select value from v$diag_info where name='Default Trace File';
使用工具格式化trace文件
[oracle@rac1 trace]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename Use 'schema.tablename' with 'explain=' option.
explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.
print=integer List only the first 'integer' SQL statements.
aggregate=yes|no
insert=filename List SQL statements and data inside INSERT statements.
sys=no TKPROF does not list SQL statements run as user SYS.
record=filename Record non-recursive statements found in the trace file.
waits=yes|no Record summary for any wait events found in the trace file.
sort=option Set of zero or more of the following sort options:
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
格式化之后的trace
TKPROF: Release 11.2.0.4.0 - Development on Fri Aug 25 15:51:18 2017
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: PROD1_ora_32508.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
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2
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 6 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 6 0 6
Misses in library cache during parse: 1----
硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 83
Number of plan statistics captured: 1
--
-訪問路徑
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
6 6 6 VIEW (cr=6 pr=0 pw=0 time=293 us cost=4 size=644 card=14)
10 10 10 WINDOW SORT PUSHED RANK (cr=6 pr=0 pw=0 time=290 us cost=4 size=182 card=14)
14 14 14 TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=238 us cost=3 size=182 card=14)
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 7.60 7.60
********************************************************************************
SQL ID: 5dt9w7dmjqp7a Plan Hash: 0----c
此處有SQL_ID
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: 83
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS-----
#非遞歸SQL語句
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 6 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 6 0 6
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 16.10 23.71
裸trace文件
PARSING IN CURSOR 部分：
Len: 被解析SQL的長度
Dep: 產生遞歸SQL的深度
Uid：user id
Otc: Oracle command type 命令的類型
Lid: 私有用戶id
Tim：時間戳
Hv： hash value
Ad：SQL address
PARSE,EXEC,FETCH 部分
C: 消耗的CPU time
E：elapsed time 操作的用時
P: physical reads 物理讀的次數
Cr: consistent reads 一致性方式讀取的數據塊
Cu：current 方式讀取的數據塊
Mis：cursor misss in cache 硬分析次數
R: -rows 處理的行數
Dep: depth 遞歸SQL的深度
Og： optimizer goal 優化器模式
Tim：timestamp時間戳
STATS 部分：
Id: 執行計劃的行源號
Cnt：當前行源返回的行數
Pid：當前行源號的父號
Pos：執行計劃中的位置
Obj：當前操作的對象id（如果當前行原始一個對象的話）
Op：當前行源的數據訪問操作
Trace file /u01/app/oracle/diag/rdbms/prod/PROD1/trace/PROD1_ora_32508.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/11.2.0
System name: Linux
Node name: rac1
Release: 2.6.32-431.el6.x86_64
Version: #1 SMP Sun Nov 10 22:19:54 EST 2013
Machine: x86_64
VM name: VMWare Version: 6
Instance name: PROD1
Redo thread mounted by this instance: 1
Oracle process number: 50
Unix process pid: 32508, image: oracle@rac1 (TNS V1-V3)
*** 2017-08-25 15:40:37.519
*** SESSION ID:(42.691) 2017-08-25 15:40:37.519
*** CLIENT ID:() 2017-08-25 15:40:37.519
*** SERVICE NAME:(SYS$USERS) 2017-08-25 15:40:37.519
*** MODULE NAME:(SQL*Plus) 2017-08-25 15:40:37.519
*** ACTION NAME:() 2017-08-25 15:40:37.519
WAIT #139754621488360: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646837519024
*** 2017-08-25 15:40:53.628
WAIT #139754621488360: nam='SQL*Net message from client' ela= 16109440 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853628880
CLOSE #139754621488360:c=0,e=7,dep=0,type=1,tim=1503646853628983
=====================
PARSING IN CURSOR #139754621554208 len=183 dep=0 uid=83 oct=3 lid=83 tim=1503646853634437 hv=2495311492 ad='8369e2d0' sqlid='gn1w5juabqvn4'
select *
from (select deptno,
ename,
sal,
row_number() over(partition by deptno order by sal desc) rn
from emp)
where rn <= 2
END OF STMT
PARSE #139754621554208:c=2000,e=5415,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3291446077,tim=1503646853634432
EXEC #139754621554208:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3291446077,tim=1503646853634605
WAIT #139754621554208: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853634674
FETCH #139754621554208:c=0,e=289,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=3291446077,tim=1503646853635022
WAIT #139754621554208: nam='SQL*Net message from client' ela= 311 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853635376
WAIT #139754621554208: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646853635422
FETCH #139754621554208:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=5,dep=0,og=1,plh=3291446077,tim=1503646853635451
STAT #139754621554208 id=1 cnt=6 pid=0 pos=1 obj=0 op='VIEW (cr=6 pr=0 pw=0 time=293 us cost=4 size=644 card=14)'
STAT #139754621554208 id=2 cnt=10 pid=1 pos=1 obj=0 op='WINDOW SORT PUSHED RANK (cr=6 pr=0 pw=0 time=290 us cost=4 size=182 card=14)'
STAT #139754621554208 id=3 cnt=14 pid=2 pos=1 obj=87108 op='TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=238 us cost=3 size=182 card=14)'
*** 2017-08-25 15:41:01.238
WAIT #139754621554208: nam='SQL*Net message from client' ela= 7601437 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1503646861238782
CLOSE #139754621554208:c=0,e=12,dep=0,type=0,tim=1503646861238957
=====================
PARSING IN CURSOR #139754621485288 len=56 dep=0 uid=83 oct=42 lid=83 tim=1503646861239192 hv=1729844458 ad='0' sqlid='5dt9w7dmjqp7a'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #139754621485288:c=0,e=151,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1503646861239192
EXEC #139754621485288:c=1000,e=309,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1503646861239561
