转载自：《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打开方法
463
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
