<<Oracle数据库性能优化艺术（第五期）>> 第11周 sql_trace及10046

1.演示使用SQL_TRACE和10046事件对其它回话进行跟踪，并给出trace结果。
SQL_TRACE演示
SQL> select value from v$diag_info where name like 'Default Trace File';

VALUE
------------------------------------------------------------------------------

c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6744.trc

SQL> alter session set sql_trace=true;

Session altered.

SQL> select count(*) from dept where deptno=10;

  COUNT(*)
----------
         1

SQL> alter session set sql_trace=false;

Session altered.

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6744.trc

...
=====================
PARSING IN CURSOR #5 len=32 dep=0 uid=84 oct=42 lid=84 tim=15700809216 hv=1569151342 ad='8dbfed0' sqlid='4tk6t8tfsfqbf'
alter session set sql_trace=true
END OF STMT
EXEC #5:c=0,e=125,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=15700809206

*** 2013-12-10 14:48:44.342
CLOSE #5:c=0,e=16,dep=0,type=0,tim=15714864489
=====================
...
=====================
PARSING IN CURSOR #2 len=41 dep=0 uid=84 oct=3 lid=84 tim=15714948048 hv=849721809 ad='2320dc64' sqlid='3px4w98tabffj'
select count(*) from dept where deptno=10
END OF STMT
PARSE #2:c=31200,e=83300,p=5,cr=254,cu=0,mis=1,r=0,dep=0,og=1,plh=2236899148,tim=15714948047
EXEC #2:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=15714948162
FETCH #2:c=0,e=2119,p=1,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=15714950358
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=1 pw=0 time=0 us)'
STAT #2 id=2 cnt=1 pid=1 pos=1 obj=73195 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=1 pw=0 time=0 us cost=1 size=13 card=1)'
FETCH #2:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=15714950920

*** 2013-12-10 14:48:56.872
CLOSE #2:c=0,e=34,dep=0,type=0,tim=15727399013
=====================
PARSING IN CURSOR #3 len=33 dep=0 uid=84 oct=42 lid=84 tim=15727400020 hv=525901419 ad='8dbfed0' sqlid='aam2chsgpj7mb'
alter session set sql_trace=false
END OF STMT
PARSE #3:c=0,e=755,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=15727400018
EXEC #3:c=0,e=160,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=15727400309


10046事件演示
SQL> select value from v$diag_info where name like 'Default Trace File';

VALUE
-------------------------------------------------------------------------------------------

c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7240.trc

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

Session altered.

SQL> select count(*) from dept where deptno=10;

  COUNT(*)
----------
         1

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

Session altered.

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7240.trc

Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7240.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1
CPU                 : 4 - type 586, 2 Physical Cores
Process Affinity    : 0x0x00000000
Memory (Avail/Total): Ph:1244M/3509M, Ph+PgF:5274M/7604M, VA:1360M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 7240, image: ORACLE.EXE (SHAD)


*** 2013-12-10 14:53:07.043
*** SESSION ID:(134.19) 2013-12-10 14:53:07.043
*** CLIENT ID:() 2013-12-10 14:53:07.043
*** SERVICE NAME:(D11R2I) 2013-12-10 14:53:07.043
*** MODULE NAME:(SQL*Plus) 2013-12-10 14:53:07.043
*** ACTION NAME:() 2013-12-10 14:53:07.043
 
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=15977546304

*** 2013-12-10 14:53:16.965
WAIT #2: nam='SQL*Net message from client' ela= 9921704 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=15987470050
CLOSE #2:c=0,e=15,dep=0,type=1,tim=15987470369
=====================
PARSING IN CURSOR #3 len=41 dep=0 uid=84 oct=3 lid=84 tim=15987470546 hv=849721809 ad='2320dc64' sqlid='3px4w98tabffj'
select count(*) from dept where deptno=10
END OF STMT
PARSE #3:c=0,e=114,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=15987470545
EXEC #3:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=15987470699
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=15987470786
FETCH #3:c=0,e=33,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=15987470866
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=73195 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=0 us cost=1 size=13 card=1)'
WAIT #3: nam='SQL*Net message from client' ela= 515 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=15987471477
FETCH #3:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=15987471543
WAIT #3: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=15987471589

*** 2013-12-10 14:53:53.017
WAIT #3: nam='SQL*Net message from client' ela= 36048464 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16023520078
CLOSE #3:c=0,e=30,dep=0,type=0,tim=16023520388
=====================
PARSING IN CURSOR #5 len=55 dep=0 uid=84 oct=42 lid=84 tim=16023520584 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #5:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16023520584
EXEC #5:c=0,e=863,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16023521533

--EOF--

2.演示10046 level 1,4,8,12的区别。

10046 level 1 (仅显示基本信息, 与SQL_TRACE得到的内容一致)

SQL> select value from v$diag_info where name like 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_4920.trc

SQL> var dno number;
SQL> exec :dno := 10;

PL/SQL procedure successfully completed.

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

Session altered.

SQL> select count(*) from dept where deptno=:dno;

  COUNT(*)
----------
         1

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

Session altered.

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

n