<<Oracle数据库性能优化艺术（第五期）>> 第11周 sql_trace及10046
2014-02-16 15:38
621 查看
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_4920.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_4920.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:1257M/3509M, Ph+PgF:5288M/7604M, VA:1360M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 4920, image: ORACLE.EXE (SHAD)
*** 2013-12-10 14:59:24.010
*** SESSION ID:(132.59) 2013-12-10 14:59:24.010
*** CLIENT ID:() 2013-12-10 14:59:24.010
*** SERVICE NAME:(D11R2I) 2013-12-10 14:59:24.010
*** MODULE NAME:(SQL*Plus) 2013-12-10 14:59:24.010
*** ACTION NAME:() 2013-12-10 14:59:24.010
CLOSE #3:c=0,e=13,dep=0,type=1,tim=16354503391
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16354506027 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=249,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=16354506025
EXEC #2:c=0,e=800,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2236899148,tim=16354506898
FETCH #2:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16354507009
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 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=16354507512
*** 2013-12-10 14:59:30.546
CLOSE #2:c=0,e=25,dep=0,type=0,tim=16361031293
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16361031546 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16361031546
EXEC #3:c=0,e=825,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16361032434
10046 level 4 (额外显示绑定变量的值)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.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 4';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.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:1249M/3509M, Ph+PgF:5280M/7604M, VA:1360M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6316, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:01:05.489
*** SESSION ID:(132.63) 2013-12-10 15:01:05.489
*** CLIENT ID:() 2013-12-10 15:01:05.489
*** SERVICE NAME:(D11R2I) 2013-12-10 15:01:05.489
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:01:05.489
*** ACTION NAME:() 2013-12-10 15:01:05.489
CLOSE #3:c=0,e=14,dep=0,type=1,tim=16455977741
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16455980170 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16455980169
BINDS #2:
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=08e4d84c bln=22 avl=02 flg=05
value=10
EXEC #2:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16455980369
FETCH #2:c=0,e=22,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16455980456
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 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=16455980936
*** 2013-12-10 15:01:09.670
CLOSE #2:c=0,e=32,dep=0,type=0,tim=16460156496
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16460156763 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16460156763
EXEC #3:c=0,e=824,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16460157652
10046 level 8 (额外显示等待事件)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.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 8';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.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:1253M/3509M, Ph+PgF:5284M/7604M, VA:1361M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6368, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:02:36.970
*** SESSION ID:(134.31) 2013-12-10 15:02:36.970
*** CLIENT ID:() 2013-12-10 15:02:36.970
*** SERVICE NAME:(D11R2I) 2013-12-10 15:02:36.970
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:02:36.970
*** ACTION NAME:() 2013-12-10 15:02:36.970
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16547444359
*** 2013-12-10 15:02:42.383
WAIT #3: nam='SQL*Net message from client' ela= 5413322 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552860167
CLOSE #3:c=0,e=13,dep=0,type=1,tim=16552860378
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16552860499 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16552860498
EXEC #2:c=0,e=138,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16552860728
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552860800
FETCH #2:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16552860850
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 pw=0 time=0 us cost=1 size=13 card=1)'
WAIT #2: nam='SQL*Net message from client' ela= 374 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552861311
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=16552861370
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552861456
*** 2013-12-10 15:02:46.455
WAIT #2: nam='SQL*Net message from client' ela= 4069718 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16556931236
CLOSE #2:c=0,e=20,dep=0,type=1,tim=16556931500
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16556931580 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16556931580
EXEC #3:c=0,e=835,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16556932477
10046 level 12 (额外显示绑定变量的值和等待事件, 相当于level 4+level 8)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.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 12';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.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:1243M/3509M, Ph+PgF:5270M/7604M, VA:1356M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6768, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:03:51.492
*** SESSION ID:(134.41) 2013-12-10 15:03:51.492
*** CLIENT ID:() 2013-12-10 15:03:51.492
*** SERVICE NAME:(D11R2I) 2013-12-10 15:03:51.492
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:03:51.492
*** ACTION NAME:() 2013-12-10 15:03:51.492
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16621965429
*** 2013-12-10 15:03:56.391
WAIT #3: nam='SQL*Net message from client' ela= 4899749 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626867121
CLOSE #3:c=0,e=15,dep=0,type=1,tim=16626867377
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16626867496 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16626867494
BINDS #2:
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=0d9bc95c bln=22 avl=02 flg=05
value=10
EXEC #2:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16626867700
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626867769
FETCH #2:c=0,e=32,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16626867827
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 pw=0 time=0 us cost=1 size=13 card=1)'
WAIT #2: nam='SQL*Net message from client' ela= 459 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626868374
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=16626868453
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626868505
*** 2013-12-10 15:04:00.276
WAIT #2: nam='SQL*Net message from client' ela= 3888374 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16630756903
CLOSE #2:c=0,e=19,dep=0,type=1,tim=16630757172
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16630757270 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16630757270
EXEC #3:c=0,e=811,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16630758144
--EOF--
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.trc
SQL> drop table t purge;
Table dropped.
SQL> create table t as select * from dba_objects;
Table created.
SQL> create index idx_t_objid on t(object_id);
Index created.
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
SQL> select /*+ index(t) */ * from t where object_id = 99;
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
SYS
EDITION$
99 99 TABLE
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
02-APR-10 02-APR-10 2010-04-02:13:18:39 VALID N N N 1
SQL> select /*+ full(t) */ * from t where object_id = 99;
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
SYS
EDITION$
99 99 TABLE
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
02-APR-10 02-APR-10 2010-04-02:13:18:39 VALID N N N 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
tkprof c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.trc c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.prf
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.prf
...
********************************************************************************
select /*+ index(t) */ *
from
t where object_id = 99
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 5 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 5 6 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T (cr=4 pr=5 pw=0 time=0 us cost=2 size=207 card=1)
1 INDEX RANGE SCAN IDX_T_OBJID (cr=3 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74578)
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
db file scattered read 1 0.01 0.01
SQL*Net message from client 2 6.78 6.80
********************************************************************************
select /*+ full(t) */ *
from
t where object_id = 99
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.20 724 1038 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.21 724 1040 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T (cr=1038 pr=724 pw=0 time=0 us cost=289 size=207 card=1)
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 14.08 14.08
db file scattered read 49 0.02 0.18
db file sequential read 5 0.00 0.00
********************************************************************************
...
通过比较cost, cr(逻辑读), pr(物理读)和等待事件, 可以发现使用索引的SQL性能更好.
--EOF--
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6552.trc
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
SQL> select count(*) from t,t;
COUNT(*)
----------
5251031296
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_6552.trc
(此段为Trace文件的具体信息)
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6552.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:1201M/3509M, Ph+PgF:5241M/7604M, VA:1362M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6552, image: ORACLE.EXE (SHAD)
(此段为Trace Session的具体信息)
*** 2013-12-10 15:22:36.601
*** SESSION ID:(132.82) 2013-12-10 15:22:36.601
*** CLIENT ID:() 2013-12-10 15:22:36.601
*** SERVICE NAME:(D11R2I) 2013-12-10 15:22:36.601
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:22:36.601
*** ACTION NAME:() 2013-12-10 15:22:36.601
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17747051626
*** 2013-12-10 15:23:07.099
WAIT #2: nam='SQL*Net message from client' ela= 30491563 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17777545276
CLOSE #2:c=0,e=15,dep=0,type=1,tim=17777545572
=====================
(此段为进行动态采样而执行的递归SQL)
PARSING IN CURSOR #2 len=409 dep=1 uid=84 oct=3 lid=84 tim=17777547088 hv=3899381049 ad='230dc444' sqlid='ccuwpvmn6rp9t'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("T") FULL("T") NO_PARALLEL_INDEX("T") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "T" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5") SEED (:"SYS_B_6") "T") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=465,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=17777547087
BINDS #2:
Bind#0
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3d0 bln=22 avl=01 flg=09
value=0
Bind#1
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3c0 bln=22 avl=01 flg=09
value=0
Bind#2
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3b0 bln=22 avl=02 flg=09
value=1
Bind#3
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3a0 bln=22 avl=02 flg=09
value=1
Bind#4
oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c38c bln=22 avl=05 flg=09
value=5.954631
Bind#5
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c37c bln=22 avl=02 flg=09
value=1
Bind#6
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c36c bln=22 avl=02 flg=09
value=1
EXEC #2:c=0,e=1056,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1807638002,tim=17777548247
FETCH #2:c=0,e=1022,p=0,cr=70,cu=0,mis=0,r=1,dep=1,og=1,plh=1807638002,tim=17777549290
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=70 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=4579 pid=1 pos=1 obj=74577 op='TABLE ACCESS SAMPLE T (cr=70 pr=0 pw=0 time=508 us cost=19 size=61752 card=5146)'
CLOSE #2:c=0,e=7,dep=1,type=0,tim=17777549389
=====================
(此段为进行动态采样而执行的递归SQL)
PARSING IN CURSOR #2 len=409 dep=1 uid=84 oct=3 lid=84 tim=17777549526 hv=3899381049 ad='230dc444' sqlid='ccuwpvmn6rp9t'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("T") FULL("T") NO_PARALLEL_INDEX("T") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "T" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5") SEED (:"SYS_B_6") "T") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1807638002,tim=17777549526
BINDS #2:
Bind#0
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3d0 bln=22 avl=01 flg=09
value=0
Bind#1
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3c0 bln=22 avl=01 flg=09
value=0
Bind#2
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3b0 bln=22 avl=02 flg=09
value=1
Bind#3
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3a0 bln=22 avl=02 flg=09
value=1
Bind#4
oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c38c bln=22 avl=05 flg=09
value=5.954631
Bind#5
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c37c bln=22 avl=02 flg=09
value=1
Bind#6
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c36c bln=22 avl=02 flg=09
value=1
EXEC #2:c=0,e=430,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1807638002,tim=17777550019
FETCH #2:c=0,e=803,p=0,cr=70,cu=0,mis=0,r=1,dep=1,og=1,plh=1807638002,tim=17777550839
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=70 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=4579 pid=1 pos=1 obj=74577 op='TABLE ACCESS SAMPLE T (cr=70 pr=0 pw=0 time=763 us cost=19 size=61752 card=5146)'
CLOSE #2:c=0,e=4,dep=1,type=0,tim=17777550909
=====================
(此段为主SQL)
PARSING IN CURSOR #3 len=24 dep=0 uid=84 oct=3 lid=84 tim=17777551245 hv=19075621 ad='2331aea0' sqlid='04g6hfh0k64j5'
select count(*) from t,t
END OF STMT
PARSE #3:c=0,e=5606,p=0,cr=144,cu=0,mis=1,r=0,dep=0,og=1,plh=840385502,tim=17777551244 (分析)
EXEC #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=840385502,tim=17777551325 (执行)
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17777551384 (等待事件)
WAIT #3: nam='Disk file operations I/O' ela= 479 FileOperation=2 fileno=4 filetype=2 obj#=-1 tim=17777551912 (等待事件)
FETCH #3:c=1069184053,e=1074005675,p=0,cr=2074,cu=0,mis=0,r=1,dep=0,og=1,plh=840385502,tim=18851557089 (取数据)
*** 2013-12-10 15:41:01.151 (此段为SQL执行计划)
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=2074 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=5251031296 pid=1 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=2074 pr=0 pw=0 time=1455364864 us cost=22107352 size=0 card=5913321934)' (最耗时的操作: 1455364864 - ( 379951 - 717559040 ) = 737425873 us)
STAT #3 id=3 cnt=72464 pid=2 pos=1 obj=74577 op='TABLE ACCESS FULL T (cr=1037 pr=0 pw=0 time=379951 us cost=289 size=0 card=76898)'
STAT #3 id=4 cnt=5251031296 pid=2 pos=2 obj=0 op='BUFFER SORT (cr=1037 pr=0 pw=0 time=717559040 us cost=22107063 size=0 card=76898)' (COST最高的操作)
STAT #3 id=5 cnt=72464 pid=4 pos=1 obj=74577 op='TABLE ACCESS FULL T (cr=1037 pr=0 pw=0 time=10096 us cost=287 size=0 card=76898)'
WAIT #3: nam='SQL*Net message from client' ela= 583 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=18851558662
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=840385502,tim=18851558756
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=18851558800
*** 2013-12-10 15:43:33.911
WAIT #3: nam='SQL*Net message from client' ela= 152747992 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=19004306865
CLOSE #3:c=0,e=36,dep=0,type=0,tim=19004307184
=====================
PARSING IN CURSOR #2 len=55 dep=0 uid=84 oct=42 lid=84 tim=19004307293 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #2:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=19004307292
EXEC #2:c=0,e=883,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=19004308292
参考:
了解raw trace文件的各项内容 http://www.eygle.com/archives/2005/10/aeearaw_traceia.html
--EOF--
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_4920.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_4920.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:1257M/3509M, Ph+PgF:5288M/7604M, VA:1360M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 4920, image: ORACLE.EXE (SHAD)
*** 2013-12-10 14:59:24.010
*** SESSION ID:(132.59) 2013-12-10 14:59:24.010
*** CLIENT ID:() 2013-12-10 14:59:24.010
*** SERVICE NAME:(D11R2I) 2013-12-10 14:59:24.010
*** MODULE NAME:(SQL*Plus) 2013-12-10 14:59:24.010
*** ACTION NAME:() 2013-12-10 14:59:24.010
CLOSE #3:c=0,e=13,dep=0,type=1,tim=16354503391
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16354506027 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=249,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=16354506025
EXEC #2:c=0,e=800,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2236899148,tim=16354506898
FETCH #2:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16354507009
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 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=16354507512
*** 2013-12-10 14:59:30.546
CLOSE #2:c=0,e=25,dep=0,type=0,tim=16361031293
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16361031546 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16361031546
EXEC #3:c=0,e=825,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16361032434
10046 level 4 (额外显示绑定变量的值)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.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 4';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6316.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:1249M/3509M, Ph+PgF:5280M/7604M, VA:1360M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6316, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:01:05.489
*** SESSION ID:(132.63) 2013-12-10 15:01:05.489
*** CLIENT ID:() 2013-12-10 15:01:05.489
*** SERVICE NAME:(D11R2I) 2013-12-10 15:01:05.489
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:01:05.489
*** ACTION NAME:() 2013-12-10 15:01:05.489
CLOSE #3:c=0,e=14,dep=0,type=1,tim=16455977741
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16455980170 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16455980169
BINDS #2:
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=08e4d84c bln=22 avl=02 flg=05
value=10
EXEC #2:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16455980369
FETCH #2:c=0,e=22,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16455980456
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 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=16455980936
*** 2013-12-10 15:01:09.670
CLOSE #2:c=0,e=32,dep=0,type=0,tim=16460156496
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16460156763 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16460156763
EXEC #3:c=0,e=824,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16460157652
10046 level 8 (额外显示等待事件)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.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 8';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6368.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:1253M/3509M, Ph+PgF:5284M/7604M, VA:1361M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6368, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:02:36.970
*** SESSION ID:(134.31) 2013-12-10 15:02:36.970
*** CLIENT ID:() 2013-12-10 15:02:36.970
*** SERVICE NAME:(D11R2I) 2013-12-10 15:02:36.970
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:02:36.970
*** ACTION NAME:() 2013-12-10 15:02:36.970
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16547444359
*** 2013-12-10 15:02:42.383
WAIT #3: nam='SQL*Net message from client' ela= 5413322 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552860167
CLOSE #3:c=0,e=13,dep=0,type=1,tim=16552860378
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16552860499 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16552860498
EXEC #2:c=0,e=138,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16552860728
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552860800
FETCH #2:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16552860850
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 pw=0 time=0 us cost=1 size=13 card=1)'
WAIT #2: nam='SQL*Net message from client' ela= 374 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552861311
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=16552861370
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16552861456
*** 2013-12-10 15:02:46.455
WAIT #2: nam='SQL*Net message from client' ela= 4069718 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16556931236
CLOSE #2:c=0,e=20,dep=0,type=1,tim=16556931500
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16556931580 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16556931580
EXEC #3:c=0,e=835,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16556932477
10046 level 12 (额外显示绑定变量的值和等待事件, 相当于level 4+level 8)
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.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 12';
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
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.trc
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6768.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:1243M/3509M, Ph+PgF:5270M/7604M, VA:1356M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6768, image: ORACLE.EXE (SHAD)
*** 2013-12-10 15:03:51.492
*** SESSION ID:(134.41) 2013-12-10 15:03:51.492
*** CLIENT ID:() 2013-12-10 15:03:51.492
*** SERVICE NAME:(D11R2I) 2013-12-10 15:03:51.492
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:03:51.492
*** ACTION NAME:() 2013-12-10 15:03:51.492
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16621965429
*** 2013-12-10 15:03:56.391
WAIT #3: nam='SQL*Net message from client' ela= 4899749 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626867121
CLOSE #3:c=0,e=15,dep=0,type=1,tim=16626867377
=====================
PARSING IN CURSOR #2 len=43 dep=0 uid=84 oct=3 lid=84 tim=16626867496 hv=3287755471 ad='231e0f40' sqlid='5rty1ug1zfaqg'
select count(*) from dept where deptno=:dno
END OF STMT
PARSE #2:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16626867494
BINDS #2:
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=0d9bc95c bln=22 avl=02 flg=05
value=10
EXEC #2:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2236899148,tim=16626867700
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626867769
FETCH #2:c=0,e=32,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=2236899148,tim=16626867827
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 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=0 pw=0 time=0 us cost=1 size=13 card=1)'
WAIT #2: nam='SQL*Net message from client' ela= 459 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626868374
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2236899148,tim=16626868453
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16626868505
*** 2013-12-10 15:04:00.276
WAIT #2: nam='SQL*Net message from client' ela= 3888374 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=16630756903
CLOSE #2:c=0,e=19,dep=0,type=1,tim=16630757172
=====================
PARSING IN CURSOR #3 len=55 dep=0 uid=84 oct=42 lid=84 tim=16630757270 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #3:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16630757270
EXEC #3:c=0,e=811,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=16630758144
--EOF--
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.trc
SQL> drop table t purge;
Table dropped.
SQL> create table t as select * from dba_objects;
Table created.
SQL> create index idx_t_objid on t(object_id);
Index created.
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
SQL> select /*+ index(t) */ * from t where object_id = 99;
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
SYS
EDITION$
99 99 TABLE
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
02-APR-10 02-APR-10 2010-04-02:13:18:39 VALID N N N 1
SQL> select /*+ full(t) */ * from t where object_id = 99;
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
SYS
EDITION$
99 99 TABLE
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_ TIMESTAMP STATUS T G S NAMESPACE
--------- --------- ------------------- ------- - - - ----------
EDITION_NAME
------------------------------
02-APR-10 02-APR-10 2010-04-02:13:18:39 VALID N N N 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
tkprof c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.trc c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.prf
notepad c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_7624.prf
...
********************************************************************************
select /*+ index(t) */ *
from
t where object_id = 99
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 5 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 5 6 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID T (cr=4 pr=5 pw=0 time=0 us cost=2 size=207 card=1)
1 INDEX RANGE SCAN IDX_T_OBJID (cr=3 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 74578)
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
db file scattered read 1 0.01 0.01
SQL*Net message from client 2 6.78 6.80
********************************************************************************
select /*+ full(t) */ *
from
t where object_id = 99
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.20 724 1038 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.03 0.21 724 1040 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T (cr=1038 pr=724 pw=0 time=0 us cost=289 size=207 card=1)
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 14.08 14.08
db file scattered read 49 0.02 0.18
db file sequential read 5 0.00 0.00
********************************************************************************
...
通过比较cost, cr(逻辑读), pr(物理读)和等待事件, 可以发现使用索引的SQL性能更好.
--EOF--
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？
SQL> select value from v$diag_info where name like 'Default Trace File';
VALUE
--------------------------------------------------------------------------------
c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6552.trc
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
SQL> select count(*) from t,t;
COUNT(*)
----------
5251031296
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_6552.trc
(此段为Trace文件的具体信息)
Trace file c:\app\diag\rdbms\d11r2i\d11r2i\trace\d11r2i_ora_6552.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:1201M/3509M, Ph+PgF:5241M/7604M, VA:1362M/2047M
Instance name: d11r2i
Redo thread mounted by this instance: 1
Oracle process number: 22
Windows thread id: 6552, image: ORACLE.EXE (SHAD)
(此段为Trace Session的具体信息)
*** 2013-12-10 15:22:36.601
*** SESSION ID:(132.82) 2013-12-10 15:22:36.601
*** CLIENT ID:() 2013-12-10 15:22:36.601
*** SERVICE NAME:(D11R2I) 2013-12-10 15:22:36.601
*** MODULE NAME:(SQL*Plus) 2013-12-10 15:22:36.601
*** ACTION NAME:() 2013-12-10 15:22:36.601
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17747051626
*** 2013-12-10 15:23:07.099
WAIT #2: nam='SQL*Net message from client' ela= 30491563 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17777545276
CLOSE #2:c=0,e=15,dep=0,type=1,tim=17777545572
=====================
(此段为进行动态采样而执行的递归SQL)
PARSING IN CURSOR #2 len=409 dep=1 uid=84 oct=3 lid=84 tim=17777547088 hv=3899381049 ad='230dc444' sqlid='ccuwpvmn6rp9t'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("T") FULL("T") NO_PARALLEL_INDEX("T") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "T" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5") SEED (:"SYS_B_6") "T") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=465,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=17777547087
BINDS #2:
Bind#0
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3d0 bln=22 avl=01 flg=09
value=0
Bind#1
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3c0 bln=22 avl=01 flg=09
value=0
Bind#2
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3b0 bln=22 avl=02 flg=09
value=1
Bind#3
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3a0 bln=22 avl=02 flg=09
value=1
Bind#4
oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c38c bln=22 avl=05 flg=09
value=5.954631
Bind#5
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c37c bln=22 avl=02 flg=09
value=1
Bind#6
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c36c bln=22 avl=02 flg=09
value=1
EXEC #2:c=0,e=1056,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1807638002,tim=17777548247
FETCH #2:c=0,e=1022,p=0,cr=70,cu=0,mis=0,r=1,dep=1,og=1,plh=1807638002,tim=17777549290
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=70 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=4579 pid=1 pos=1 obj=74577 op='TABLE ACCESS SAMPLE T (cr=70 pr=0 pw=0 time=508 us cost=19 size=61752 card=5146)'
CLOSE #2:c=0,e=7,dep=1,type=0,tim=17777549389
=====================
(此段为进行动态采样而执行的递归SQL)
PARSING IN CURSOR #2 len=409 dep=1 uid=84 oct=3 lid=84 tim=17777549526 hv=3899381049 ad='230dc444' sqlid='ccuwpvmn6rp9t'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("T") FULL("T") NO_PARALLEL_INDEX("T") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "T" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5") SEED (:"SYS_B_6") "T") SAMPLESUB
END OF STMT
PARSE #2:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1807638002,tim=17777549526
BINDS #2:
Bind#0
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3d0 bln=22 avl=01 flg=09
value=0
Bind#1
oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3c0 bln=22 avl=01 flg=09
value=0
Bind#2
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3b0 bln=22 avl=02 flg=09
value=1
Bind#3
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c3a0 bln=22 avl=02 flg=09
value=1
Bind#4
oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c38c bln=22 avl=05 flg=09
value=5.954631
Bind#5
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c37c bln=22 avl=02 flg=09
value=1
Bind#6
oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0924c36c bln=22 avl=02 flg=09
value=1
EXEC #2:c=0,e=430,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1807638002,tim=17777550019
FETCH #2:c=0,e=803,p=0,cr=70,cu=0,mis=0,r=1,dep=1,og=1,plh=1807638002,tim=17777550839
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=70 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=4579 pid=1 pos=1 obj=74577 op='TABLE ACCESS SAMPLE T (cr=70 pr=0 pw=0 time=763 us cost=19 size=61752 card=5146)'
CLOSE #2:c=0,e=4,dep=1,type=0,tim=17777550909
=====================
(此段为主SQL)
PARSING IN CURSOR #3 len=24 dep=0 uid=84 oct=3 lid=84 tim=17777551245 hv=19075621 ad='2331aea0' sqlid='04g6hfh0k64j5'
select count(*) from t,t
END OF STMT
PARSE #3:c=0,e=5606,p=0,cr=144,cu=0,mis=1,r=0,dep=0,og=1,plh=840385502,tim=17777551244 (分析)
EXEC #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=840385502,tim=17777551325 (执行)
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=17777551384 (等待事件)
WAIT #3: nam='Disk file operations I/O' ela= 479 FileOperation=2 fileno=4 filetype=2 obj#=-1 tim=17777551912 (等待事件)
FETCH #3:c=1069184053,e=1074005675,p=0,cr=2074,cu=0,mis=0,r=1,dep=0,og=1,plh=840385502,tim=18851557089 (取数据)
*** 2013-12-10 15:41:01.151 (此段为SQL执行计划)
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=2074 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=5251031296 pid=1 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=2074 pr=0 pw=0 time=1455364864 us cost=22107352 size=0 card=5913321934)' (最耗时的操作: 1455364864 - ( 379951 - 717559040 ) = 737425873 us)
STAT #3 id=3 cnt=72464 pid=2 pos=1 obj=74577 op='TABLE ACCESS FULL T (cr=1037 pr=0 pw=0 time=379951 us cost=289 size=0 card=76898)'
STAT #3 id=4 cnt=5251031296 pid=2 pos=2 obj=0 op='BUFFER SORT (cr=1037 pr=0 pw=0 time=717559040 us cost=22107063 size=0 card=76898)' (COST最高的操作)
STAT #3 id=5 cnt=72464 pid=4 pos=1 obj=74577 op='TABLE ACCESS FULL T (cr=1037 pr=0 pw=0 time=10096 us cost=287 size=0 card=76898)'
WAIT #3: nam='SQL*Net message from client' ela= 583 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=18851558662
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=840385502,tim=18851558756
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=18851558800
*** 2013-12-10 15:43:33.911
WAIT #3: nam='SQL*Net message from client' ela= 152747992 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=19004306865
CLOSE #3:c=0,e=36,dep=0,type=0,tim=19004307184
=====================
PARSING IN CURSOR #2 len=55 dep=0 uid=84 oct=42 lid=84 tim=19004307293 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #2:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=19004307292
EXEC #2:c=0,e=883,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=19004308292
参考:
了解raw trace文件的各项内容 http://www.eygle.com/archives/2005/10/aeearaw_traceia.html
--EOF--
内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理 
相关文章推荐
- <<Oracle数据库性能优化艺术（第五期）>> 第10周 变量邦定（包括11g下Adaptive cursor sharing技术）
- <<Oracle数据库性能优化艺术（第五期）>> 第9周 并行执行
- <<Oracle数据库性能优化艺术（第五期）>> 第8周 分析及动态采样（包括11g下的extended statistics技术）
- <<Oracle数据库性能优化艺术（第五期）>> 第7周 索引和分区（包括11g下新的组合分区）
- <<Oracle数据库性能优化艺术（第五期）>> 第6周 等待事件
- <<Oracle数据库性能优化艺术（第五期）>> 第5周 Hints
- <<Oracle数据库性能优化艺术（第五期）>> 第4周 优化器
- <<Oracle数据库性能优化艺术（第五期）>> 第3周 Latch
- <<Oracle数据库性能优化艺术（第五期）>> 第2周 锁
- <<Oracle数据库性能优化艺术（第五期）>> 第1周 性能优化综述
- oracle表空间不足扩容的方法
- Oracle创建用户,创建表空间,将空间分配给用户,给用户授权
- ORACLE SQL 高级编程--查询转换
- oracle sql
- 彻底卸载oracle11g
- vmware安装cent os 6.5 + oracle 11g xe + jboss eap 6.2 + weblogic 12c+ webshpere mq 7.5
- Oracle SQL Plus Tutorial 学习笔记
- pl/sql连接64位oracle的时候出现乱码的问题
- ORACLE行转列通用过程
- 在Oracle中创建带参数的视图