Oracle 事件跟踪优化SQL实例之（三）—10046功能

2023年11月21日 643点热度 0人点赞 0条评论

一、10046的功能分析
二、启动10046跟踪的方式
三、10046跟踪分析—演示level1,4,8,12的区别

一、10046的功能分析

1、功能介绍

10046是一个Oracle的内部事件(event)，通过设置这个事件可以得到Oracle内部执行系统解析、调用、等待、绑定变量等详细的trace信息，即帮助我们解析一条/多条SQL、PL/SQL语句的运行状态。

这些状态包括：Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等。

它不仅为我们揭示了一条、多条SQL的运行情况，同时还能帮我们分析一些DDL维护命令的内部工作原理，RMAN、Data Pump Expdp/impdp等工具缓慢问题。

对于SQL性能优化、分析系统的性能有着非常重要的作用。

2、具体内容

用于分析SQL执行过程中性能消耗情况，可以查看绑定变量信息，可以查看等待事件信息，它比SQL_TRACE输入输出更多参数。工具使用场合：

--优化SQL语句
--查看SQL语句执行计划
--跟踪SQL语句执行过程
--把会话中SQL的信息重定向到一个文件里

3、 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跟踪的方式

1、方式1：会话级别—当前session（一般是新会话）的跟踪方式：

（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

（2）执行要trace的SQL

select * from scott.dept;

（3）关闭session sql trace

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

2、方式2：进程级—Oradebug分析其他用户trace

如果需要跟踪一个已经存在session，可以用 oradebug连接到session上，并发起10046 trace。

oradebug event 10046 trace name context forever,level 12

（1）查找要跟踪的session信息：

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

（2）根据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

（3）开启进程追踪：

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

（4）执行查询：

SQL> select * from dept where deptno=10;

    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK

（5）关闭oradebug跟踪：

SQL>oradebug event 10046 trace name context off

（6）查看追踪文件并分析：

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文件，原理同上。

3、方式3：进程级—DBMS_SYSTEM.SET_EV分析其他用户trace

（1）语法格式：

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) ;

（2）查询获得需要跟踪的session信息:

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

       SID    SERIAL# USERNAME
---------- ---------- ------------------------------
       135      17081 SYS
       197      38741 SCOTT

（3）执行现有会话进程跟踪:

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

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

（4）执行查询操作：

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

    DEPTNO DNAME          LOC
---------- -------------- -------------
        10 ACCOUNTING     NEW YORK
        20 RESEARCH       DALLAS
        30 SALES          CHICAGO

（5）结束会话跟踪：

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

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

（6）跟踪文件分析：

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分析，原理同上。

三、10046跟踪分析—演示level1,4,8,12的区别

Level 1：等同于SQL_TRACE

Level 4：在Level1的基础上增加收集绑定变量的信息

Level 8：在Level1的基础上增加等待事件的信息（注意：没有收集绑定变量的信息）这个有用，如果一条SQL语句非常非常慢，可以查一下是什么原因导致的如此慢

Level 12：等同于Level 4+Level 8，即同时收集绑定变量信息和等待事件信息

1、Level 1：等同于SQL_TRACE

（1）配置

set linesize 300   
set pagesize 999
variable i number;     --定义变量
execute :i:=2;       --变量赋值

（2）开启level 1追踪

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

（3）绑定变量，重用SQL执行计划

select * from test where id=:i;

（4）关闭10046 level1追踪

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

（5）查看当前会话原始trace文件

select name,value from v$diag_info where name='Default Trace File';

（6）查看跟踪日志

*** 2023-11-22 13:59:30.582
CLOSE #140329511725072:c=13,e=13,dep=0,type=1,tim=1700632770582868
=====================
PARSING IN CURSOR #140329511701784 len=30 dep=0 uid=107 oct=3 lid=107 tim=1700632770584024 hv=3146199730 ad='1715d1fb0' sqlid='btmhxh2xsfcpk'
select * from test where id=:i    -- 我们看不到绑定变量值，只能看到它是一个绑定变量
END OF STMT
PARSE #140329511701784:c=939,e=938,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1700632770584021
EXEC #140329511701784:c=907,e=908,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700632770585090
FETCH #140329511701784:c=116,e=116,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700632770585339
FETCH #140329511701784:c=17,e=17,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700632770585701
STAT #140329511701784 id=1 cnt=1 pid=0 pos=1 obj=97551 op='TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=106 us cost=3 size=9 card=1)'

*** 2023-11-22 13:59:35.340
CLOSE #140329511701784:c=8,e=7,dep=0,type=0,tim=1700632775340894

使用的是#140329511701784游标，
PARSE #140329511701784  解析-> 
EXEC #140329511701784   执行->  
FETCH #140329511701784  取操作-> 
CLOSE #140329511701784关闭游标

=====================
PARSING IN CURSOR #140329511701784 len=55 dep=0 uid=107 oct=42 lid=107 tim=1700632775341010 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140329511701784:c=23,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700632775341009
EXEC #140329511701784:c=251,e=251,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700632775341303

2、Level 4：在这个级别中我们就可以看到绑定变量信息了

跟踪并执行

（1）开启level 4追踪

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

（3）继续绑定变量，重用SQL执行计划

select * from test where id=:i;

（4）关闭10046 level 4追踪

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

（5）查看trace

*** 2023-11-22 15:23:00.331
CLOSE #140329511705280:c=12,e=12,dep=0,type=1,tim=1700637780331969
=====================
PARSING IN CURSOR #140329511700536 len=30 dep=0 uid=107 oct=3 lid=107 tim=1700637780332102 hv=3146199730 ad='1715d1fb0' sqlid='btmhxh2xsfcpk'
select * from test where id=:i     --继续绑定变量
END OF STMT
PARSE #140329511700536:c=50,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700637780332102
BINDS #140329511700536:           --绑定的是游标：#140329511700536
Bind#0                            --0表示绑定的第一个变量  如果是1表示绑定的第二个变量，以此类推
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7fa102b243f0 bln=22 avl=02 flg=05
value=2                           --绑定的变量值
EXEC #140329511700536:c=2299,e=4466,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700637780336658
FETCH #140329511700536:c=227,e=226,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700637780336955
FETCH #140329511700536:c=13,e=12,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700637780337307
STAT #140329511700536 id=1 cnt=1 pid=0 pos=1 obj=97551 op='TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=221 us cost=3 size=9 card=1)'

*** 2023-11-22 15:23:02.867
CLOSE #140329511700536:c=6,e=6,dep=0,type=0,tim=1700637782867922
=====================
PARSING IN CURSOR #140329511720536 len=55 dep=0 uid=107 oct=42 lid=107 tim=1700637782868059 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140329511720536:c=25,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700637782868059
EXEC #140329511720536:c=249,e=249,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700637782868392

3、Level 8：这个级别中，可以显示SQL语句等待事件，但没有绑定变量

我们就可以知道SQL语句是在等待某些资源，还是没有等待资源速度就是这样了，只能提升硬件了。

（1）开启level 8追踪

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

（3）继续绑定变量，重用SQL执行计划

select * from test where id=:i order by id;

（4）关闭10046 level 8追踪

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

（5）查看trace

*** 2023-11-22 16:36:49.992
WAIT #140329511727264: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642209992778

*** 2023-11-22 16:36:54.311
WAIT #140329511727264: nam='SQL*Net message from client' ela= 4318591 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642214311435
CLOSE #140329511727264:c=6,e=7,dep=0,type=1,tim=1700642214311537
=====================
PARSING IN CURSOR #140329511731072 len=42 dep=0 uid=107 oct=3 lid=107 tim=1700642214312145 hv=3218286229 ad='168da5a30' sqlid='gqh3zyqzx69np'
select * from test where id=:i order by id
END OF STMT
PARSE #140329511731072:c=581,e=582,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1700642214312144
EXEC #140329511731072:c=445,e=445,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700642214312678
WAIT #140329511731072: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642214312727
FETCH #140329511731072:c=94,e=93,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700642214312838
WAIT #140329511731072: nam='SQL*Net message from client' ela= 171 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642214313039
FETCH #140329511731072:c=20,e=21,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700642214313075
STAT #140329511731072 id=1 cnt=1 pid=0 pos=1 obj=97551 op='TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=89 us cost=3 size=9 card=1)'
WAIT #140329511731072: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642214313155

*** 2023-11-22 16:36:59.816
WAIT #140329511731072: nam='SQL*Net message from client' ela= 5502979 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700642219816145
CLOSE #140329511731072:c=6,e=5,dep=0,type=0,tim=1700642219816258

这次使用新的游标，标红的都是标识SQL语句WAIT等待事件，这几个等待事件都是正常的等待客户端发送命令的事件，说明我们的SQL语句效率都挺高的
=====================
PARSING IN CURSOR #140329511731072 len=55 dep=0 uid=107 oct=42 lid=107 tim=1700642219816312 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140329511731072:c=18,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700642219816311
EXEC #140329511731072:c=214,e=215,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700642219816560

4、Level 12：这个级别即可以显示绑定变量，又可以显示等待事件

（1）开启level 12追踪

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

（3）继续绑定变量，重用SQL执行计划

select * from test where id=:i order by id;

（4）关闭10046 level 12追踪

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

（5）查看trace

*** 2023-11-22 17:02:28.941
WAIT #140329511720536: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643748941431

*** 2023-11-22 17:02:42.688
WAIT #140329511720536: nam='SQL*Net message from client' ela= 13747197 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643762688711
CLOSE #140329511720536:c=15,e=14,dep=0,type=1,tim=1700643762688822
=====================
PARSING IN CURSOR #140329511652736 len=42 dep=0 uid=107 oct=3 lid=107 tim=1700643762688908 hv=3218286229 ad='168da5a30' sqlid='gqh3zyqzx69np'
select * from test where id=:i order by id
END OF STMT
PARSE #140329511652736:c=58,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700643762688907
BINDS #140329511652736:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7fa102b1cbd8 bln=22 avl=02 flg=05
value=2
EXEC #140329511652736:c=132,e=183,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700643762689145
WAIT #140329511652736: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643762689190
FETCH #140329511652736:c=139,e=139,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1700643762689342
WAIT #140329511652736: nam='SQL*Net message from client' ela= 160 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643762689550
FETCH #140329511652736:c=16,e=16,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1700643762689581
STAT #140329511652736 id=1 cnt=1 pid=0 pos=1 obj=97551 op='TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=134 us cost=3 size=9 card=1)'
WAIT #140329511652736: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643762689644

*** 2023-11-22 17:02:44.221
WAIT #140329511652736: nam='SQL*Net message from client' ela= 1531401 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1700643764221052
CLOSE #140329511652736:c=6,e=6,dep=0,type=0,tim=1700643764221165
=====================
PARSING IN CURSOR #140329511652736 len=55 dep=0 uid=107 oct=42 lid=107 tim=1700643764221228 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140329511652736:c=29,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700643764221227
EXEC #140329511652736:c=221,e=221,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1700643764221496

本作品采用知识共享署名 4.0 国际许可协议进行许可