【性能优化】 之10046 事件
2014-01-23 13:59
309 查看
1.演示使用SQL_TRACE和10046事件对其它回话进行跟踪，并给出trace结果。<br>
2.演示10046 level 1,4,8,12的区别。<br>
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。<br>
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，
特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？<br>
====================================================================================================
答：
1.演示使用SQL_TRACE和10046事件对其它会话进行跟踪，并给出trace结果。<br>
1.1 建立测试环境表
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL*Plus: Release 11.2.0.1.0 Production on Sat Dec 14 10:09:09 2013
Copyright (c) 1982, 2010, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> select distinct sid from v$mystat;
SID
----------
43
SQL>
drop table t11;
CREATE TABLE T11 AS SELECT * FROM DBA_OBJECTS;
1.2 打开一个SQL 窗口，执行一段代码：
SQL> select distinct sid from v$mystat;
SID
----------
102
SQL>
SQL> BEGIN
2 FOR I IN 1..1000000 LOOP
3 EXECUTE IMMEDIATE 'SELECT * FROM TANG.T11 WHERE OBJECT_ID='||I;
4 END LOOP;
5 END;
6 /
1.3同时另打开一个窗口，登录，并查询当前执行的SQL 情况，可以查询到现在有几个用户在。
select ss.USERNAME,sid,ss.SERIAL#,sql_text from v$process pr,v$session ss,v$sqlarea sa where pr.addr=ss.paddr and ss.sql_hash_value=sa.hash_value and ss.USERNAME in ('TANG','TEST');
USERNAME MACHINE SID SERIAL# SPID SQL_TEXT SQL_ID
1 TANG WORKGROUP\MDATABASE3 102 14981 5424 BEGIN FOR I IN 1..1000000 LOOP EXECUTE IMMEDIATE 'SELECT * FROM T11 WHERE OBJECT_ID='||I; END LOOP; END; 7wut5k7hcv0xx
2 TANG WORKGROUP\MDATABASE3 221 18007 2764 select ss.USERNAME,ss.MACHINE,sid,ss.SERIAL#,SPID,sql_text,sa.sql_id from v$process pr,v$session ss,v$sqlarea sa where pr.addr=ss.paddr and ss.sql_hash_value=sa.hash_value and ss.USERNAME in (:"SYS_B_0",:"SYS_B_1")
36k2d8gvx4497
1.4 可以看到，除了本查询窗口，还有另外一个用户，同时也可以看到登录的账号名称，
可以从这些信息确认你要跟踪的用户。
也可以直接按SID 查询到用户
select sid,serial# from v$session where sid in (144,12);
1.5 我们现在来跟踪 另外一个SESSION:
SQL> execute sys.dbms_system.set_sql_trace_in_session(143,21889,true);
begin sys.dbms_system.set_sql_trace_in_session(122,42649,true); end;
ORA-06550: line 1, column 7:
PLS-00201: identifier 'SYS.DBMS_SYSTEM' must be declared
ORA-06550: line 1, column 7:
PL/SQL: Statement ignored
SQL> CONNECT SYS/SYS AS SYSDBA
SQL> grant execute on dbms_system to tang;
SQL> CONNECT TANG/TANG
SQL> execute sys.dbms_system.set_sql_trace_in_session(102,15297,true);
PL/SQL 过程已成功完成。
1.6 打开跟踪的同时，再在 SID=102 会话窗口执行其它的SQL,以方便跟踪查看：
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> execute sys.dbms_system.set_sql_trace_in_session(102,15297,false);
PL/SQL 过程已成功完成。
1.7 在跟踪窗口，查看跟踪文件：
SQL> select * from v$diag_info where name like 'Default Trace File';
INST_ID NAME VALUE
---------- ------------------- --------------------------------------------------------------------------------
1 Default Trace File D:\APP\ORACLE\diag\rdbms\orcl\orcl\trace\orcl_ora_6120.trc
我按此文件查找，就是没有找到跟踪文件，还使用了
SQL> alter session set tracefile_identifier='tang';
设置指定 文件标识的方法，也没有生成跟踪文件。退出SQLPLUS 窗口也还没有。
后看文件日期，查看到最后修改时间的文件，并查看文件内容。
看到有个最新文件 orcl_ora_5384.trc 里，是有我刚才跟踪内容的，如下：
=====================
PARSING IN CURSOR #381493544 len=62 dep=0 uid=99 oct=3 lid=99 tim=9072280544623 hv=926194785 ad='2aff29070' sqlid='9n8fv7hvm9731'
SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #381493544:c=15600,e=22433,p=0,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=4132580237,tim=9072280544622
EXEC #381493544:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072280544700
FETCH #381493544:c=15601,e=16891,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9072280561656
STAT #381493544 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=16886 us)'
STAT #381493544 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=96000 us cost=305 size=0 card=76393)'
FETCH #381493544:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9072280562178
*** 2013-12-14 11:35:01.692
CLOSE #381493544:c=0,e=10,dep=0,type=0,tim=9072281919840
=====================
PARSING IN CURSOR #381493544 len=62 dep=0 uid=99 oct=3 lid=99 tim=9072281920021 hv=926194785 ad='2aff29070' sqlid='9n8fv7hvm9731'
SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #381493544:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072281920020
EXEC #381493544:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072281920105
FETCH #381493544:c=15600,e=12407,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9072281932582
STAT #381493544 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12404 us)'
STAT #381493544 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=76830 us cost=305 size=0 card=76393)'
FETCH #381493544:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9072281933094
*** 2013-12-14 11:36:20.024
XCTEND rlbk=0, rd_only=1, tim=9072360240234
=====================
使用TKPROF 生成文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_5384.trc trace_test.log
可以看到，我执行的3次查询情况：
SQL ID: 9n8fv7hvm9731 Plan Hash: 4132580237
SELECT /*+ trace_102_session_by_tang */ count(*)
from
tang.t11
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.00 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 10 0.06 0.06 0 5465 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20 0.06 0.07 0 5465 0 5
Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: 99
Number of plan statistics captured: 5
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1093 pr=0 pw=0 time=13213 us)
76393 76393 76393 TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=80020 us cost=305 size=0 card=76393)
********************************************************************************
因为前面也有执行过此查询，但没有找到跟踪文件，后来又再执行过，所以这里看到分析，执行次数并不是列出的3次。
1.8 使用10046 进行跟踪：
SQL> select sid,serial# from v$session where sid in (102,122);
SID SERIAL#
---------- ----------
102 15309
122 46489
SQL>
在SID=122 窗口进行跟踪 102
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> execute sys.dbms_system.set_ev(102,15309,10046,12,NULL);
在SID=102 窗口执行SQL
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL>
查看跟踪文件：（没再按查询到的文件名找了，找最新新文件，并且在服务器端直接打开SQL操作，
发现这样生成跟踪文件比在远程登录打开SQL更快。）
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073169651776 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=15600,e=24720,p=0,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=4132580237,tim=9073169651774
EXEC #389842728:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073169651852
WAIT #389842728: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169651912
FETCH #389842728:c=15600,e=12316,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073169664258
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12311 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=73864 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 378 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169664796
FETCH #389842728:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073169664842
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169664872
*** 2013-12-14 11:49:55.454
WAIT #389842728: nam='SQL*Net message from client' ela= 5961094 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175625984
CLOSE #389842728:c=0,e=13,dep=0,type=0,tim=9073175626385
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073175626532 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073175626530
EXEC #389842728:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073175626625
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175626685
FETCH #389842728:c=15600,e=12316,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073175639031
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12313 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=73891 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 413 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175639599
FETCH #389842728:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073175639645
WAIT #389842728: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175639674
*** 2013-12-14 11:49:56.250
WAIT #389842728: nam='SQL*Net message from client' ela= 779901 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176419594
CLOSE #389842728:c=0,e=9,dep=0,type=0,tim=9073176419684
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073176419784 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073176419782
EXEC #389842728:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073176419865
WAIT #389842728: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176419919
FETCH #389842728:c=15600,e=12151,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073176432098
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12147 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=74387 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 402 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176432639
FETCH #389842728:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073176432684
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176432714
生成可读性强的日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_4552.trc trace_10046.lo
g
TKPROF: Release 11.2.0.3.0 - Development on 星期六 12月 14 11:51:05 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
SQL ID: 2n106hhasy6c0 Plan Hash: 4132580237
SELECT /*+ 10046_TRACE_session_by_tang */ count(*)
from
tang.t11
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.01 0.02 0 30 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 6 0.04 0.03 0 3279 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.06 0.06 0 3309 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 99
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12257 us)
76393 76393 76393 TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=74047 us cost=305 size=0 card=76393)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 5 5.96 6.74
查询30次，分析3次，执行3次。可能我执行的alter system flush shared_pool; 还是没有起到作用。
虽然添加 的/*+ 10046_TRACE_session_by_tang */ 不相同，但还是做同一个分析了。
但可以看到，跟踪其他SESSION是成功的。
***************************************************************************************************
2.演示10046 level 1,4,8,12的区别。<br>
10046事件不同级别：追踪的信息列表：
Level 1：等同于SQL_TRACE
Level 4：在Level1的基础上增加收集绑定变量的信息
Level 8：在Level1的基础上增加等待事件的信息，这个有用，如果一条SQL语句非常非常慢，可以查一下是什么原因导致的如此慢
Level 12：等同于Level 4+Level 8，即同时收集绑定变量信息和等待事件信息
总结：级别高的包含级别低
2.1 级别 1
SQL> create table t10046 as select * from dba_objects;
表已创建。
SQL> set linesize 800;
SQL> set pagesize 400;
SQL> variable i number;
SQL> execute :i:=10;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 1';
会话已更改。
SQL> select * from t10046 where object_id=:i;
OWNER OBJECT_NAME
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CRE
ATED LAST_DDL_TIME TIMESTAMP STATUS T G S NAMESPACE EDITION_
NAME
------------------------------ -------------------------------------------------
-------------------------------------------------------------------------------
------------------------------ ---------- -------------- ------------------- ---
----------- -------------- ------------------- ------- - - - ---------- --------
----------------------
SYS C_USER#
10 10 CLUSTER 03-
11月-11 03-11月-11 2011-11-03:05:39:13 VALID N N N 5
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>
查看原始TRACE 文件： 看到的查询是绑定变量值 i
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9088407988616 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=708,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9088407988614
=====================
mis=1 我们进行了一次硬解析
使用tkprof 生成文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2036.trc t_10046_l1.log
SYS=NO
********************************************************************************
SQL ID: 49r1yrn62fruw Plan Hash: 725540078
select *
from
t10046 where object_id=:i
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 1 0 0
Fetch 2 0.01 0.03 722 1095 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.03 722 1096 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS FULL T10046 (cr=1095 pr=722 pw=0 time=201 us cost=306 size=2484 card=12)
********************************************************************************
2.2 级别 4
为了和上次的区别，把变量修改成100； 并打开10046 级别4 进行跟踪
SQL> execute :i:=100;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 4';
会话已更改。
SQL> select * from t10046 where object_id=:i;
OWNER OBJECT_NAME
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CRE
ATED LAST_DDL_TIME TIMESTAMP STATUS T G S NAMESPACE EDITION_
NAME
------------------------------ -------------------------------------------------
-------------------------------------------------------------------------------
------------------------------ ---------- -------------- ------------------- ---
----------- -------------- ------------------- ------- - - - ---------- --------
----------------------
SYS ORA$BASE
100 EDITION 03-
11月-11 03-11月-11 2011-11-03:05:39:15 VALID N N N 64
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL> exit
从 Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options 断
开
C:\Users\Administrator>
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9088407988616 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=708,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9088407988614
=====================
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9089082374623 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082374621
BINDS #360760104:
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=16bef7b8 bln=22 avl=02 flg=05
value=100
EXEC #360760104:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082374896
FETCH #360760104:c=0,e=76,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=725540078,tim=9089082375056
FETCH #360760104:c=0,e=7199,p=0,cr=1090,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082382888
STAT #360760104 id=1 cnt=1 pid=0 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1095 pr=0 pw=0 time=68 us cost=306 size=2484 card=12)'
*** 2013-12-14 16:15:14.061
CLOSE #360760104:c=0,e=11,dep=0,type=0,tim=9089093411332
=====================
mis=0 我们没有进行硬解析，是一次软解析。 Bind#0 绑定了一个变量，变量值为： value=100。
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2036.trc t_10046_l4.log
SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期六 12月 14 16:20:03 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
********************************************************************************
SQL ID: 49r1yrn62fruw Plan Hash: 725540078
select *
from
t10046 where object_id=:i
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 1 0 0
Fetch 4 0.01 0.03 722 2190 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.01 0.04 722 2191 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS FULL T10046 (cr=1095 pr=361 pw=0 time=135 us cost=306 size=2484 card=12)
********************************************************************************
2.3 级别 8
SQL> alter session set events '10046 trace name context forever,level 8';
会话已更改。
SQL> variable i number;
SQL> execute :i:=200;
PL/SQL 过程已成功完成。
SQL> select *from t10046 where object_id=:i group by object_name;
select *from t10046 where object_id=:i group by object_name
*
第 1 行出现错误:
ORA-00979: 不是 GROUP BY 表达式
SQL> select count(0) from t10046 where object_id=:i group by object_name;
COUNT(0)
----------
1
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>
日志文件内容：
可以看到下面日志中，列出每一次执行后面的等待事件：
PARSING IN CURSOR #402683680 len=76 dep=0 uid=84 oct=3 lid=84 tim=9173041983514 hv=2990142783 ad='2ad7dfc60' sqlid='3qbav5yt3mx9z'
select count(:"SYS_B_0") from t10046 where object_id=:i group by object_name
END OF STMT
PARSE #402683680:c=0,e=381,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9173041983512
EXEC #402683680:c=0,e=954,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1268764439,tim=9173041984522
WAIT #402683680: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041984603
FETCH #402683680:c=15600,e=6369,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=1268764439,tim=9173041991002
WAIT #402683680: nam='SQL*Net message from client' ela= 413 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041991514
FETCH #402683680:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1268764439,tim=9173041991593
STAT #402683680 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=1093 pr=0 pw=0 time=6387 us cost=306 size=30 card=1)'
STAT #402683680 id=2 cnt=1 pid=1 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=6151 us cost=305 size=30 card=1)'
WAIT #402683680: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041991698
*** 2013-12-15 15:34:55.262
WAIT #402683680: nam='SQL*Net message from client' ela= 28114898 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173070106616
CLOSE #402683680:c=0,e=12,dep=0,type=0,tim=9173070107011
=====================
使用TKPROF 生成可读性好的日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_5788.trc t_10046_l8.log
SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 15:41:32 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
SQL ID: 3qbav5yt3mx9z Plan Hash: 1268764439
select count(:"SYS_B_0")
from
t10046 where object_id=:i group by object_name
#列出了变量名称
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.00 0 1093 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 HASH GROUP BY (cr=1093 pr=0 pw=0 time=6387 us cost=306 size=30 card=1)
1 1 1 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=6151 us cost=305 size=30 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 28.11 28.11
********************************************************************************
日志内容中有了等待时间的统计：28.11
2.4 级别 12
#重新登录SQLPLUS
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL> variable i number;
SQL> execute :i:=400;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 12';
会话已更改。
SQL> select count(*) from t10046 where object_id=:i group by object_name;
COUNT(*)
----------
1
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>exit #退出SQLPLUS 以方便更快的生成跟踪文件
PARSING IN CURSOR #407177392 len=67 dep=0 uid=84 oct=3 lid=84 tim=9173741336916 hv=3013006604 ad='181f2a378' sqlid='0vc1sj6ttdp8c'
select count(*) from t10046 where object_id=:i group by object_name
END OF STMT
PARSE #407177392:c=0,e=356,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9173741336915
BINDS #407177392: #绑定变量
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=184cffe8 bln=22 avl=02 flg=05
value=400 #绑定变量的值
EXEC #407177392:c=0,e=1057,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1268764439,tim=9173741338035
WAIT #407177392: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741338101
FETCH #407177392:c=0,e=6173,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=1268764439,tim=9173741344304
WAIT #407177392: nam='SQL*Net message from client' ela= 431 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741344798
FETCH #407177392:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1268764439,tim=9173741344877
STAT #407177392 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=1093 pr=0 pw=0 time=6199 us cost=306 size=30 card=1)'
STAT #407177392 id=2 cnt=1 pid=1 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=5976 us cost=305 size=30 card=1)'
WAIT #407177392: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741344982
*** 2013-12-15 15:46:11.552
WAIT #407177392: nam='SQL*Net message from client' ela= 5004356 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173746349358
CLOSE #407177392:c=0,e=15,dep=0,type=0,tim=9173746349676
=====================
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_4828.trc t_10046_l12.lo
g SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 15:48:48 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
生成的日志文件内容如下：
SQL ID: 0vc1sj6ttdp8c Plan Hash: 1268764439
select count(*)
from
t10046 where object_id=:i group by object_name
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 1093 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1093 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 HASH GROUP BY (cr=1093 pr=0 pw=0 time=6199 us cost=306 size=30 card=1)
1 1 1 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=5976 us cost=305 size=30 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 5.00 5.00
********************************************************************************
***************************************************************************************************
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。<br>
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL*Plus: Release 11.2.0.3.0 Production on 星期日 12月 15 15:57:29 2013
Copyright (c) 1982, 2011, Oracle. All rights reserved.
连接到:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> alter system flush shared_pool; #清空缓存
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL>alter session set sql_trace=true; 启动SQL_TRACE
第一条查询语句：
SQL> select object_type,count(0) from t10046 where object_id between 500 and 300
0 group by object_type;
OBJECT_TYPE COUNT(0)
------------------- ----------
SEQUENCE 27
LOB 64
PACKAGE 6
PACKAGE BODY 3
INDEX 346
TABLE 287
SYNONYM 848
VIEW 851
CLUSTER 2
TYPE 67
已选择10行。
第二条查询语句：
SQL> select object_type,count(0) from (select * from t10046 ) A where object_id betw
een 500 and 3000 group by object_type;
OBJECT_TYPE COUNT(0)
------------------- ----------
SEQUENCE 27
LOB 64
PACKAGE 6
PACKAGE BODY 3
INDEX 346
TABLE 287
SYNONYM 848
VIEW 851
CLUSTER 2
TYPE 67
已选择10行。
SQL>alter session set sql_trace=false; 关闭SQL_TRACE
使用tkprof 生成可读性日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2232.trc t_sql_trace.lo
g SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 16:04:11 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
D:\app\oracle\diag\rdbms\orcl\orcl\trace>
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 16:04:11 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: orcl_ora_2232.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: 4tk6t8tfsfqbf Plan Hash: 0
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 54 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 54 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
********************************************************************************
#第一条查询语句
总花费时间：time=7969
总成本 ：cost=306
SQL ID: 41ahrzcgp1s9y Plan Hash: 4217418775
select object_type,count(:"SYS_B_0")
from
t10046 where object_id between :"SYS_B_1" and :"SYS_B_2" group by
object_type
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 1093 0 10
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
10 10 10 HASH GROUP BY (cr=1093 pr=0 pw=0 time=7969 us cost=306 size=630 card=45)
2501 2501 2501 FILTER (cr=1093 pr=0 pw=0 time=7111 us)
2501 2501 2501 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=2730 us cost=305 size=27370 card=1955)
********************************************************************************
第二条SQL
总花费时间：time=7999
总成本 ：cost=306
两条SQL 只有在总花费时间上有差异，其它都一致。从花费时间上可以看出，第一条SQL
优于第二条
********************************************************************************
SQL ID: 3976y1bzms06j Plan Hash: 4217418775
select object_type,count(:"SYS_B_0")
from
(select * from t10046 ) A where object_id between :"SYS_B_1" and :"SYS_B_2"
group by object_type
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 1093 0 10
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
10 10 10 HASH GROUP BY (cr=1093 pr=0 pw=0 time=7999 us cost=306 size=630 card=45)
2501 2501 2501 FILTER (cr=1093 pr=0 pw=0 time=7235 us)
2501 2501 2501 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=2604 us cost=305 size=27370 card=1955)
********************************************************************************
***************************************************************************************************
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，
特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？<br>
对测试库中的一个事件表进行查询第一次登录记录
--select count(0) from MACH.M_MACHINE_EVENT
---36539216
select count(0) from MACH.M_MACHINE_EVENT t where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489'
--390
select * from MACH.M_MACHINE_EVENT t
where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489'
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489')
SQL> alter system flush shared_pool; #清空缓存
原始sql_trace 跟踪文件内容如下：
PARSING IN CURSOR部分
说明：游标号：#402965288，这个游标号是可以重用的，这个游标指向的是我们执行的SQL产生的递归语句（红色部分），它是把对象属性写入数据字典中进行登记，好为以后的应用做语法语义校验的
len=178 执行的SQL长度
dep=0 递归的SQL深度，0层递归
uid=84 用户id 84
oct=3 oracle commend type 命令类型
lid=85 私有用户id 85也代表leo1用户
tim=9176765823354 时间戳
hv=1851603686 have value SQL的哈希值
ad='2aea53d88' SQL address SQL的地址
cr 一致性读 84
mis 1 一次硬分析
og：=1 ; #Optimizer goal，优化目标: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
=====================
PARSING IN CURSOR #402965288 len=178 dep=0 uid=84 oct=3 lid=84
tim=9176765823354 hv=1851603686 ad='2aea53d88' sqlid='gs6sc4jr5ufr6'
select * from MACH.M_MACHINE_EVENT t
where machine_id=:"SYS_B_0"
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id=:"SYS_B_1")
END OF STMT
PARSE #402965288:c=15600,e=6233,p=0,cr=84,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9176765823352
=====================
这部分是读取直方图信息的内容
使用了RULE og=3
E=26 ELAPSED TIME 操作花费的时间
因为这个表非常大，可以看到，在读直方图数据时，花费的资源也不少。因为这条语句本身只返回一条
记录，重要的消耗在查询过程
从下面几个返回的数据可以看到，ORACLE把 各种访问的数据都读到内存中，
索引的访问，排序，全表搜索各种统计数据。
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813836 pr=813819 pw=0 time=20681157 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813835 pr=813819 pw=0 time=20681142 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813832 pr=813819 pw=0 time=20681118 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813832 pr=813819 pw=0 time=3080 us cost=221307 size=780 card=30)'
PARSING IN CURSOR #403343152 len=210 dep=1 uid=0 oct=3 lid=0 tim=9176765823901 hv=864012087 ad='2ade32b30' sqlid='96g93hntrzjtr'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
EXEC #403343152:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765823899
FETCH #403343152:c=0,e=22,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765823974
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824006
EXEC #403343152:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824101
FETCH #403343152:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824170
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824203
EXEC #403343152:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824453
FETCH #403343152:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824493
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824525
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824584
FETCH #403343152:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824621
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824652
EXEC #403343152:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824710
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824746
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765824776
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824834
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824870
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824901
EXEC #403343152:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824959
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824995
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825025
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825083
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825119
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825150
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825208
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825244
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825274
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825333
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825368
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825399
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825457
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825493
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825523
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825581
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825617
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825647
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825705
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825741
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825772
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825830
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825865
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825895
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825954
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825990
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826020
EXEC #403343152:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826089
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826125
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826155
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826215
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826251
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826282
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826340
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826376
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826410
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826468
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826504
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826535
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826593
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826629
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826659
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826717
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826752
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826783
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826841
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826877
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826907
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826965
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765827001
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765827031
EXEC #402965288:c=4446028,e=20685362,p=813819,cr=813901,cu=1,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176786508776
FETCH #402965288:c=0,e=40,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3487993498,tim=9176786509463
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813836 pr=813819 pw=0 time=20681157 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813835 pr=813819 pw=0 time=20681142 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813832 pr=813819 pw=0 time=20681118 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813832 pr=813819 pw=0 time=3080 us cost=221307 size=780 card=30)'
FETCH #402965288:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3487993498,tim=9176786510407
CLOSE #402965288:c=0,e=14,dep=0,type=0,tim=9176928387795
=====================
PARSING IN CURSOR #402965288 len=178 dep=0 uid=84 oct=3 lid=84 tim=9176928388636 hv=1851603686 ad='2aea53d88' sqlid='gs6sc4jr5ufr6'
select * from MACH.M_MACHINE_EVENT t
where machine_id=:"SYS_B_0"
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id=:"SYS_B_1")
END OF STMT
下面是SQL
PARSE EXEC FETCH部分
c=0 消耗的CPU时间
e=100 这步操作的总用时
p=0 物理读的次数
cr=0 一致性读的次数（也叫数据块数），这个一致性读跟数据块在内存中还是硬盘中是没有关系的，它代表就需要读这么多次而已。如果要找的数据没有在内存中就会触发一次物理读
cu=0 current方式读的次数（数据块数）
mis=0 硬解析的次数
r=1 rows处理的行数
dep=1 递归的SQL深度
og=1 optimizer goal优化其模式
tim=9176928388634 时间戳
plh=3487993498 plan hash value 执行计划的哈希值
PARSE #402965288:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176928388634
*** 2013-12-15 16:39:34.500
STAT 部分
id=1 执行计划的行源号，每一层都有一个号，从上往下 1 2 3 4 排列
cnt=1 当前行源号返回的行数
pid=0 行源号的父号，如果当前行源号是4 父号就是3 是1父号就是0
这也标识了执行计划的执行顺序4 -> 3 -> 2 -> 1
obj=76192 当前操作的对象id
从下面的执行部分，也可以看到执行计划的步骤内容
从索引返回记录读取：TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT
(cr=813835 pr=813819 pw=0 time=20695423 us cost=3 size=153 card=1)
使用了唯一索引 INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID
有一次性读取 813834，物理读取数据块数 813819，时间：20695408，成本：2
(cr=813834 pr=813819 pw=0 time=20695408 us cost=2 size=0 card=1)
排序花费：
SORT AGGREGATE (cr=813831 pr=813819 pw=0 time=20695385 us)
从这些解读可以看出，在执行计划过程中物理读上花费了很多成本。所以可以考虑在字段machine_id添加索引，
以减少物理读。
EXEC #402965288:c=4461629,e=20695435,p=813819,cr=813831,cu=1,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176949084157
FETCH #402965288:c=0,e=39,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3487993498,tim=9176949084564
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813835 pr=813819 pw=0 time=20695423 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813834 pr=813819 pw=0 time=20695408 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813831 pr=813819 pw=0 time=20695385 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813831 pr=813819 pw=0 time=8236 us cost=221307 size=780 card=30)'
FETCH #402965288:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3487993498,tim=9176949085339
*** 2013-12-15 16:39:59.493
CLOSE #402965288:c=0,e=15,dep=0,type=0,tim=9176974078551
=====================
2.演示10046 level 1,4,8,12的区别。<br>
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。<br>
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，
特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？<br>
====================================================================================================
答：
1.演示使用SQL_TRACE和10046事件对其它会话进行跟踪，并给出trace结果。<br>
1.1 建立测试环境表
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL*Plus: Release 11.2.0.1.0 Production on Sat Dec 14 10:09:09 2013
Copyright (c) 1982, 2010, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> select distinct sid from v$mystat;
SID
----------
43
SQL>
drop table t11;
CREATE TABLE T11 AS SELECT * FROM DBA_OBJECTS;
1.2 打开一个SQL 窗口，执行一段代码：
SQL> select distinct sid from v$mystat;
SID
----------
102
SQL>
SQL> BEGIN
2 FOR I IN 1..1000000 LOOP
3 EXECUTE IMMEDIATE 'SELECT * FROM TANG.T11 WHERE OBJECT_ID='||I;
4 END LOOP;
5 END;
6 /
1.3同时另打开一个窗口，登录，并查询当前执行的SQL 情况，可以查询到现在有几个用户在。
select ss.USERNAME,sid,ss.SERIAL#,sql_text from v$process pr,v$session ss,v$sqlarea sa where pr.addr=ss.paddr and ss.sql_hash_value=sa.hash_value and ss.USERNAME in ('TANG','TEST');
USERNAME MACHINE SID SERIAL# SPID SQL_TEXT SQL_ID
1 TANG WORKGROUP\MDATABASE3 102 14981 5424 BEGIN FOR I IN 1..1000000 LOOP EXECUTE IMMEDIATE 'SELECT * FROM T11 WHERE OBJECT_ID='||I; END LOOP; END; 7wut5k7hcv0xx
2 TANG WORKGROUP\MDATABASE3 221 18007 2764 select ss.USERNAME,ss.MACHINE,sid,ss.SERIAL#,SPID,sql_text,sa.sql_id from v$process pr,v$session ss,v$sqlarea sa where pr.addr=ss.paddr and ss.sql_hash_value=sa.hash_value and ss.USERNAME in (:"SYS_B_0",:"SYS_B_1")
36k2d8gvx4497
1.4 可以看到，除了本查询窗口，还有另外一个用户，同时也可以看到登录的账号名称，
可以从这些信息确认你要跟踪的用户。
也可以直接按SID 查询到用户
select sid,serial# from v$session where sid in (144,12);
1.5 我们现在来跟踪 另外一个SESSION:
SQL> execute sys.dbms_system.set_sql_trace_in_session(143,21889,true);
begin sys.dbms_system.set_sql_trace_in_session(122,42649,true); end;
ORA-06550: line 1, column 7:
PLS-00201: identifier 'SYS.DBMS_SYSTEM' must be declared
ORA-06550: line 1, column 7:
PL/SQL: Statement ignored
SQL> CONNECT SYS/SYS AS SYSDBA
SQL> grant execute on dbms_system to tang;
SQL> CONNECT TANG/TANG
SQL> execute sys.dbms_system.set_sql_trace_in_session(102,15297,true);
PL/SQL 过程已成功完成。
1.6 打开跟踪的同时，再在 SID=102 会话窗口执行其它的SQL,以方便跟踪查看：
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> execute sys.dbms_system.set_sql_trace_in_session(102,15297,false);
PL/SQL 过程已成功完成。
1.7 在跟踪窗口，查看跟踪文件：
SQL> select * from v$diag_info where name like 'Default Trace File';
INST_ID NAME VALUE
---------- ------------------- --------------------------------------------------------------------------------
1 Default Trace File D:\APP\ORACLE\diag\rdbms\orcl\orcl\trace\orcl_ora_6120.trc
我按此文件查找，就是没有找到跟踪文件，还使用了
SQL> alter session set tracefile_identifier='tang';
设置指定 文件标识的方法，也没有生成跟踪文件。退出SQLPLUS 窗口也还没有。
后看文件日期，查看到最后修改时间的文件，并查看文件内容。
看到有个最新文件 orcl_ora_5384.trc 里，是有我刚才跟踪内容的，如下：
=====================
PARSING IN CURSOR #381493544 len=62 dep=0 uid=99 oct=3 lid=99 tim=9072280544623 hv=926194785 ad='2aff29070' sqlid='9n8fv7hvm9731'
SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #381493544:c=15600,e=22433,p=0,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=4132580237,tim=9072280544622
EXEC #381493544:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072280544700
FETCH #381493544:c=15601,e=16891,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9072280561656
STAT #381493544 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=16886 us)'
STAT #381493544 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=96000 us cost=305 size=0 card=76393)'
FETCH #381493544:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9072280562178
*** 2013-12-14 11:35:01.692
CLOSE #381493544:c=0,e=10,dep=0,type=0,tim=9072281919840
=====================
PARSING IN CURSOR #381493544 len=62 dep=0 uid=99 oct=3 lid=99 tim=9072281920021 hv=926194785 ad='2aff29070' sqlid='9n8fv7hvm9731'
SELECT /*+ trace_102_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #381493544:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072281920020
EXEC #381493544:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9072281920105
FETCH #381493544:c=15600,e=12407,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9072281932582
STAT #381493544 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12404 us)'
STAT #381493544 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=76830 us cost=305 size=0 card=76393)'
FETCH #381493544:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9072281933094
*** 2013-12-14 11:36:20.024
XCTEND rlbk=0, rd_only=1, tim=9072360240234
=====================
使用TKPROF 生成文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_5384.trc trace_test.log
可以看到，我执行的3次查询情况：
SQL ID: 9n8fv7hvm9731 Plan Hash: 4132580237
SELECT /*+ trace_102_session_by_tang */ count(*)
from
tang.t11
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 5 0.00 0.00 0 0 0 0
Execute 5 0.00 0.00 0 0 0 0
Fetch 10 0.06 0.06 0 5465 0 5
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20 0.06 0.07 0 5465 0 5
Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: 99
Number of plan statistics captured: 5
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1093 pr=0 pw=0 time=13213 us)
76393 76393 76393 TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=80020 us cost=305 size=0 card=76393)
********************************************************************************
因为前面也有执行过此查询，但没有找到跟踪文件，后来又再执行过，所以这里看到分析，执行次数并不是列出的3次。
1.8 使用10046 进行跟踪：
SQL> select sid,serial# from v$session where sid in (102,122);
SID SERIAL#
---------- ----------
102 15309
122 46489
SQL>
在SID=122 窗口进行跟踪 102
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> alter system flush shared_pool;
系统已更改。
SQL> execute sys.dbms_system.set_ev(102,15309,10046,12,NULL);
在SID=102 窗口执行SQL
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL> SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11;
COUNT(*)
----------
76393
SQL>
查看跟踪文件：（没再按查询到的文件名找了，找最新新文件，并且在服务器端直接打开SQL操作，
发现这样生成跟踪文件比在远程登录打开SQL更快。）
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073169651776 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=15600,e=24720,p=0,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=4132580237,tim=9073169651774
EXEC #389842728:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073169651852
WAIT #389842728: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169651912
FETCH #389842728:c=15600,e=12316,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073169664258
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12311 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=73864 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 378 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169664796
FETCH #389842728:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073169664842
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073169664872
*** 2013-12-14 11:49:55.454
WAIT #389842728: nam='SQL*Net message from client' ela= 5961094 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175625984
CLOSE #389842728:c=0,e=13,dep=0,type=0,tim=9073175626385
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073175626532 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073175626530
EXEC #389842728:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073175626625
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175626685
FETCH #389842728:c=15600,e=12316,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073175639031
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12313 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=73891 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 413 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175639599
FETCH #389842728:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073175639645
WAIT #389842728: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073175639674
*** 2013-12-14 11:49:56.250
WAIT #389842728: nam='SQL*Net message from client' ela= 779901 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176419594
CLOSE #389842728:c=0,e=9,dep=0,type=0,tim=9073176419684
=====================
PARSING IN CURSOR #389842728 len=64 dep=0 uid=99 oct=3 lid=99 tim=9073176419784 hv=361699712 ad='2b0f3fbb8' sqlid='2n106hhasy6c0'
SELECT /*+ 10046_TRACE_session_by_tang */ count(*) from tang.t11
END OF STMT
PARSE #389842728:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073176419782
EXEC #389842728:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4132580237,tim=9073176419865
WAIT #389842728: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176419919
FETCH #389842728:c=15600,e=12151,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=4132580237,tim=9073176432098
STAT #389842728 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12147 us)'
STAT #389842728 id=2 cnt=76393 pid=1 pos=1 obj=97630 op='TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=74387 us cost=305 size=0 card=76393)'
WAIT #389842728: nam='SQL*Net message from client' ela= 402 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176432639
FETCH #389842728:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4132580237,tim=9073176432684
WAIT #389842728: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9073176432714
生成可读性强的日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_4552.trc trace_10046.lo
g
TKPROF: Release 11.2.0.3.0 - Development on 星期六 12月 14 11:51:05 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
SQL ID: 2n106hhasy6c0 Plan Hash: 4132580237
SELECT /*+ 10046_TRACE_session_by_tang */ count(*)
from
tang.t11
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.01 0.02 0 30 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 6 0.04 0.03 0 3279 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.06 0.06 0 3309 0 3
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 99
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1093 pr=0 pw=0 time=12257 us)
76393 76393 76393 TABLE ACCESS FULL T11 (cr=1093 pr=0 pw=0 time=74047 us cost=305 size=0 card=76393)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 5 5.96 6.74
查询30次，分析3次，执行3次。可能我执行的alter system flush shared_pool; 还是没有起到作用。
虽然添加 的/*+ 10046_TRACE_session_by_tang */ 不相同，但还是做同一个分析了。
但可以看到，跟踪其他SESSION是成功的。
***************************************************************************************************
2.演示10046 level 1,4,8,12的区别。<br>
10046事件不同级别：追踪的信息列表：
Level 1：等同于SQL_TRACE
Level 4：在Level1的基础上增加收集绑定变量的信息
Level 8：在Level1的基础上增加等待事件的信息，这个有用，如果一条SQL语句非常非常慢，可以查一下是什么原因导致的如此慢
Level 12：等同于Level 4+Level 8，即同时收集绑定变量信息和等待事件信息
总结：级别高的包含级别低
2.1 级别 1
SQL> create table t10046 as select * from dba_objects;
表已创建。
SQL> set linesize 800;
SQL> set pagesize 400;
SQL> variable i number;
SQL> execute :i:=10;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 1';
会话已更改。
SQL> select * from t10046 where object_id=:i;
OWNER OBJECT_NAME
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CRE
ATED LAST_DDL_TIME TIMESTAMP STATUS T G S NAMESPACE EDITION_
NAME
------------------------------ -------------------------------------------------
-------------------------------------------------------------------------------
------------------------------ ---------- -------------- ------------------- ---
----------- -------------- ------------------- ------- - - - ---------- --------
----------------------
SYS C_USER#
10 10 CLUSTER 03-
11月-11 03-11月-11 2011-11-03:05:39:13 VALID N N N 5
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>
查看原始TRACE 文件： 看到的查询是绑定变量值 i
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9088407988616 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=708,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9088407988614
=====================
mis=1 我们进行了一次硬解析
使用tkprof 生成文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2036.trc t_10046_l1.log
SYS=NO
********************************************************************************
SQL ID: 49r1yrn62fruw Plan Hash: 725540078
select *
from
t10046 where object_id=:i
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 1 0 0
Fetch 2 0.01 0.03 722 1095 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.03 722 1096 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS FULL T10046 (cr=1095 pr=722 pw=0 time=201 us cost=306 size=2484 card=12)
********************************************************************************
2.2 级别 4
为了和上次的区别，把变量修改成100； 并打开10046 级别4 进行跟踪
SQL> execute :i:=100;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 4';
会话已更改。
SQL> select * from t10046 where object_id=:i;
OWNER OBJECT_NAME
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CRE
ATED LAST_DDL_TIME TIMESTAMP STATUS T G S NAMESPACE EDITION_
NAME
------------------------------ -------------------------------------------------
-------------------------------------------------------------------------------
------------------------------ ---------- -------------- ------------------- ---
----------- -------------- ------------------- ------- - - - ---------- --------
----------------------
SYS ORA$BASE
100 EDITION 03-
11月-11 03-11月-11 2011-11-03:05:39:15 VALID N N N 64
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL> exit
从 Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options 断
开
C:\Users\Administrator>
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9088407988616 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=708,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9088407988614
=====================
=====================
PARSING IN CURSOR #360760104 len=39 dep=0 uid=84 oct=3 lid=84 tim=9089082374623 hv=203906908 ad='2b0de0dc8' sqlid='49r1yrn62fruw'
select * from t10046 where object_id=:i
END OF STMT
PARSE #360760104:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082374621
BINDS #360760104:
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=16bef7b8 bln=22 avl=02 flg=05
value=100
EXEC #360760104:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082374896
FETCH #360760104:c=0,e=76,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=725540078,tim=9089082375056
FETCH #360760104:c=0,e=7199,p=0,cr=1090,cu=0,mis=0,r=0,dep=0,og=1,plh=725540078,tim=9089082382888
STAT #360760104 id=1 cnt=1 pid=0 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1095 pr=0 pw=0 time=68 us cost=306 size=2484 card=12)'
*** 2013-12-14 16:15:14.061
CLOSE #360760104:c=0,e=11,dep=0,type=0,tim=9089093411332
=====================
mis=0 我们没有进行硬解析，是一次软解析。 Bind#0 绑定了一个变量，变量值为： value=100。
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2036.trc t_10046_l4.log
SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期六 12月 14 16:20:03 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
********************************************************************************
SQL ID: 49r1yrn62fruw Plan Hash: 725540078
select *
from
t10046 where object_id=:i
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 1 0 0
Fetch 4 0.01 0.03 722 2190 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.01 0.04 722 2191 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS FULL T10046 (cr=1095 pr=361 pw=0 time=135 us cost=306 size=2484 card=12)
********************************************************************************
2.3 级别 8
SQL> alter session set events '10046 trace name context forever,level 8';
会话已更改。
SQL> variable i number;
SQL> execute :i:=200;
PL/SQL 过程已成功完成。
SQL> select *from t10046 where object_id=:i group by object_name;
select *from t10046 where object_id=:i group by object_name
*
第 1 行出现错误:
ORA-00979: 不是 GROUP BY 表达式
SQL> select count(0) from t10046 where object_id=:i group by object_name;
COUNT(0)
----------
1
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>
日志文件内容：
可以看到下面日志中，列出每一次执行后面的等待事件：
PARSING IN CURSOR #402683680 len=76 dep=0 uid=84 oct=3 lid=84 tim=9173041983514 hv=2990142783 ad='2ad7dfc60' sqlid='3qbav5yt3mx9z'
select count(:"SYS_B_0") from t10046 where object_id=:i group by object_name
END OF STMT
PARSE #402683680:c=0,e=381,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9173041983512
EXEC #402683680:c=0,e=954,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1268764439,tim=9173041984522
WAIT #402683680: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041984603
FETCH #402683680:c=15600,e=6369,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=1268764439,tim=9173041991002
WAIT #402683680: nam='SQL*Net message from client' ela= 413 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041991514
FETCH #402683680:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1268764439,tim=9173041991593
STAT #402683680 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=1093 pr=0 pw=0 time=6387 us cost=306 size=30 card=1)'
STAT #402683680 id=2 cnt=1 pid=1 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=6151 us cost=305 size=30 card=1)'
WAIT #402683680: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173041991698
*** 2013-12-15 15:34:55.262
WAIT #402683680: nam='SQL*Net message from client' ela= 28114898 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173070106616
CLOSE #402683680:c=0,e=12,dep=0,type=0,tim=9173070107011
=====================
使用TKPROF 生成可读性好的日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_5788.trc t_10046_l8.log
SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 15:41:32 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
SQL ID: 3qbav5yt3mx9z Plan Hash: 1268764439
select count(:"SYS_B_0")
from
t10046 where object_id=:i group by object_name
#列出了变量名称
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.00 0 1093 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 HASH GROUP BY (cr=1093 pr=0 pw=0 time=6387 us cost=306 size=30 card=1)
1 1 1 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=6151 us cost=305 size=30 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 28.11 28.11
********************************************************************************
日志内容中有了等待时间的统计：28.11
2.4 级别 12
#重新登录SQLPLUS
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL> variable i number;
SQL> execute :i:=400;
PL/SQL 过程已成功完成。
SQL> alter session set events '10046 trace name context forever,level 12';
会话已更改。
SQL> select count(*) from t10046 where object_id=:i group by object_name;
COUNT(*)
----------
1
SQL> alter session set events '10046 trace name context off';
会话已更改。
SQL>exit #退出SQLPLUS 以方便更快的生成跟踪文件
PARSING IN CURSOR #407177392 len=67 dep=0 uid=84 oct=3 lid=84 tim=9173741336916 hv=3013006604 ad='181f2a378' sqlid='0vc1sj6ttdp8c'
select count(*) from t10046 where object_id=:i group by object_name
END OF STMT
PARSE #407177392:c=0,e=356,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9173741336915
BINDS #407177392: #绑定变量
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=184cffe8 bln=22 avl=02 flg=05
value=400 #绑定变量的值
EXEC #407177392:c=0,e=1057,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1268764439,tim=9173741338035
WAIT #407177392: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741338101
FETCH #407177392:c=0,e=6173,p=0,cr=1093,cu=0,mis=0,r=1,dep=0,og=1,plh=1268764439,tim=9173741344304
WAIT #407177392: nam='SQL*Net message from client' ela= 431 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741344798
FETCH #407177392:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1268764439,tim=9173741344877
STAT #407177392 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=1093 pr=0 pw=0 time=6199 us cost=306 size=30 card=1)'
STAT #407177392 id=2 cnt=1 pid=1 pos=1 obj=97804 op='TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=5976 us cost=305 size=30 card=1)'
WAIT #407177392: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173741344982
*** 2013-12-15 15:46:11.552
WAIT #407177392: nam='SQL*Net message from client' ela= 5004356 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=9173746349358
CLOSE #407177392:c=0,e=15,dep=0,type=0,tim=9173746349676
=====================
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_4828.trc t_10046_l12.lo
g SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 15:48:48 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
生成的日志文件内容如下：
SQL ID: 0vc1sj6ttdp8c Plan Hash: 1268764439
select count(*)
from
t10046 where object_id=:i group by object_name
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 1093 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1093 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 HASH GROUP BY (cr=1093 pr=0 pw=0 time=6199 us cost=306 size=30 card=1)
1 1 1 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=5976 us cost=305 size=30 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 5.00 5.00
********************************************************************************
***************************************************************************************************
3.自己构造两条完成同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧优劣。<br>
C:\Users\Administrator>sqlplus tang/sa@orcl
SQL*Plus: Release 11.2.0.3.0 Production on 星期日 12月 15 15:57:29 2013
Copyright (c) 1982, 2011, Oracle. All rights reserved.
连接到:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> alter system flush shared_pool; #清空缓存
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL> /
系统已更改。
SQL>alter session set sql_trace=true; 启动SQL_TRACE
第一条查询语句：
SQL> select object_type,count(0) from t10046 where object_id between 500 and 300
0 group by object_type;
OBJECT_TYPE COUNT(0)
------------------- ----------
SEQUENCE 27
LOB 64
PACKAGE 6
PACKAGE BODY 3
INDEX 346
TABLE 287
SYNONYM 848
VIEW 851
CLUSTER 2
TYPE 67
已选择10行。
第二条查询语句：
SQL> select object_type,count(0) from (select * from t10046 ) A where object_id betw
een 500 and 3000 group by object_type;
OBJECT_TYPE COUNT(0)
------------------- ----------
SEQUENCE 27
LOB 64
PACKAGE 6
PACKAGE BODY 3
INDEX 346
TABLE 287
SYNONYM 848
VIEW 851
CLUSTER 2
TYPE 67
已选择10行。
SQL>alter session set sql_trace=false; 关闭SQL_TRACE
使用tkprof 生成可读性日志文件
D:\app\oracle\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_2232.trc t_sql_trace.lo
g SYS=NO
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 16:04:11 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
D:\app\oracle\diag\rdbms\orcl\orcl\trace>
TKPROF: Release 11.2.0.3.0 - Development on 星期日 12月 15 16:04:11 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: orcl_ora_2232.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: 4tk6t8tfsfqbf Plan Hash: 0
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 54 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 54 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
********************************************************************************
#第一条查询语句
总花费时间：time=7969
总成本 ：cost=306
SQL ID: 41ahrzcgp1s9y Plan Hash: 4217418775
select object_type,count(:"SYS_B_0")
from
t10046 where object_id between :"SYS_B_1" and :"SYS_B_2" group by
object_type
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 1093 0 10
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
10 10 10 HASH GROUP BY (cr=1093 pr=0 pw=0 time=7969 us cost=306 size=630 card=45)
2501 2501 2501 FILTER (cr=1093 pr=0 pw=0 time=7111 us)
2501 2501 2501 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=2730 us cost=305 size=27370 card=1955)
********************************************************************************
第二条SQL
总花费时间：time=7999
总成本 ：cost=306
两条SQL 只有在总花费时间上有差异，其它都一致。从花费时间上可以看出，第一条SQL
优于第二条
********************************************************************************
SQL ID: 3976y1bzms06j Plan Hash: 4217418775
select object_type,count(:"SYS_B_0")
from
(select * from t10046 ) A where object_id between :"SYS_B_1" and :"SYS_B_2"
group by object_type
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.00 0 1093 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 1093 0 10
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
10 10 10 HASH GROUP BY (cr=1093 pr=0 pw=0 time=7999 us cost=306 size=630 card=45)
2501 2501 2501 FILTER (cr=1093 pr=0 pw=0 time=7235 us)
2501 2501 2501 TABLE ACCESS FULL T10046 (cr=1093 pr=0 pw=0 time=2604 us cost=305 size=27370 card=1955)
********************************************************************************
***************************************************************************************************
4.做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，
特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？<br>
对测试库中的一个事件表进行查询第一次登录记录
--select count(0) from MACH.M_MACHINE_EVENT
---36539216
select count(0) from MACH.M_MACHINE_EVENT t where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489'
--390
select * from MACH.M_MACHINE_EVENT t
where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489'
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id='55ADE930-5FDF-5EC4-8429-15640684C489')
SQL> alter system flush shared_pool; #清空缓存
原始sql_trace 跟踪文件内容如下：
PARSING IN CURSOR部分
说明：游标号：#402965288，这个游标号是可以重用的，这个游标指向的是我们执行的SQL产生的递归语句（红色部分），它是把对象属性写入数据字典中进行登记，好为以后的应用做语法语义校验的
len=178 执行的SQL长度
dep=0 递归的SQL深度，0层递归
uid=84 用户id 84
oct=3 oracle commend type 命令类型
lid=85 私有用户id 85也代表leo1用户
tim=9176765823354 时间戳
hv=1851603686 have value SQL的哈希值
ad='2aea53d88' SQL address SQL的地址
cr 一致性读 84
mis 1 一次硬分析
og：=1 ; #Optimizer goal，优化目标: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
=====================
PARSING IN CURSOR #402965288 len=178 dep=0 uid=84 oct=3 lid=84
tim=9176765823354 hv=1851603686 ad='2aea53d88' sqlid='gs6sc4jr5ufr6'
select * from MACH.M_MACHINE_EVENT t
where machine_id=:"SYS_B_0"
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id=:"SYS_B_1")
END OF STMT
PARSE #402965288:c=15600,e=6233,p=0,cr=84,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=9176765823352
=====================
这部分是读取直方图信息的内容
使用了RULE og=3
E=26 ELAPSED TIME 操作花费的时间
因为这个表非常大，可以看到，在读直方图数据时，花费的资源也不少。因为这条语句本身只返回一条
记录，重要的消耗在查询过程
从下面几个返回的数据可以看到，ORACLE把 各种访问的数据都读到内存中，
索引的访问，排序，全表搜索各种统计数据。
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813836 pr=813819 pw=0 time=20681157 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813835 pr=813819 pw=0 time=20681142 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813832 pr=813819 pw=0 time=20681118 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813832 pr=813819 pw=0 time=3080 us cost=221307 size=780 card=30)'
PARSING IN CURSOR #403343152 len=210 dep=1 uid=0 oct=3 lid=0 tim=9176765823901 hv=864012087 ad='2ade32b30' sqlid='96g93hntrzjtr'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
EXEC #403343152:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765823899
FETCH #403343152:c=0,e=22,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765823974
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824006
EXEC #403343152:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824101
FETCH #403343152:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824170
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824203
EXEC #403343152:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824453
FETCH #403343152:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824493
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824525
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824584
FETCH #403343152:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824621
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824652
EXEC #403343152:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824710
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824746
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765824776
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824834
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824870
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765824901
EXEC #403343152:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765824959
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765824995
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825025
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825083
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825119
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825150
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825208
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825244
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825274
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825333
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825368
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825399
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825457
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825493
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825523
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825581
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825617
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825647
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825705
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825741
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765825772
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825830
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825865
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765825895
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765825954
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765825990
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826020
EXEC #403343152:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826089
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826125
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826155
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826215
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826251
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826282
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826340
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826376
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826410
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826468
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826504
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826535
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826593
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826629
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826659
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826717
FETCH #403343152:c=0,e=16,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826752
CLOSE #403343152:c=0,e=6,dep=1,type=3,tim=9176765826783
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826841
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765826877
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765826907
EXEC #403343152:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,plh=2239883476,tim=9176765826965
FETCH #403343152:c=0,e=17,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=9176765827001
CLOSE #403343152:c=0,e=5,dep=1,type=3,tim=9176765827031
EXEC #402965288:c=4446028,e=20685362,p=813819,cr=813901,cu=1,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176786508776
FETCH #402965288:c=0,e=40,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3487993498,tim=9176786509463
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813836 pr=813819 pw=0 time=20681157 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813835 pr=813819 pw=0 time=20681142 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813832 pr=813819 pw=0 time=20681118 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813832 pr=813819 pw=0 time=3080 us cost=221307 size=780 card=30)'
FETCH #402965288:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3487993498,tim=9176786510407
CLOSE #402965288:c=0,e=14,dep=0,type=0,tim=9176928387795
=====================
PARSING IN CURSOR #402965288 len=178 dep=0 uid=84 oct=3 lid=84 tim=9176928388636 hv=1851603686 ad='2aea53d88' sqlid='gs6sc4jr5ufr6'
select * from MACH.M_MACHINE_EVENT t
where machine_id=:"SYS_B_0"
and event_id=(select min(event_id)
from MACH.M_MACHINE_EVENT
where machine_id=:"SYS_B_1")
END OF STMT
下面是SQL
PARSE EXEC FETCH部分
c=0 消耗的CPU时间
e=100 这步操作的总用时
p=0 物理读的次数
cr=0 一致性读的次数（也叫数据块数），这个一致性读跟数据块在内存中还是硬盘中是没有关系的，它代表就需要读这么多次而已。如果要找的数据没有在内存中就会触发一次物理读
cu=0 current方式读的次数（数据块数）
mis=0 硬解析的次数
r=1 rows处理的行数
dep=1 递归的SQL深度
og=1 optimizer goal优化其模式
tim=9176928388634 时间戳
plh=3487993498 plan hash value 执行计划的哈希值
PARSE #402965288:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176928388634
*** 2013-12-15 16:39:34.500
STAT 部分
id=1 执行计划的行源号，每一层都有一个号，从上往下 1 2 3 4 排列
cnt=1 当前行源号返回的行数
pid=0 行源号的父号，如果当前行源号是4 父号就是3 是1父号就是0
这也标识了执行计划的执行顺序4 -> 3 -> 2 -> 1
obj=76192 当前操作的对象id
从下面的执行部分，也可以看到执行计划的步骤内容
从索引返回记录读取：TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT
(cr=813835 pr=813819 pw=0 time=20695423 us cost=3 size=153 card=1)
使用了唯一索引 INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID
有一次性读取 813834，物理读取数据块数 813819，时间：20695408，成本：2
(cr=813834 pr=813819 pw=0 time=20695408 us cost=2 size=0 card=1)
排序花费：
SORT AGGREGATE (cr=813831 pr=813819 pw=0 time=20695385 us)
从这些解读可以看出，在执行计划过程中物理读上花费了很多成本。所以可以考虑在字段machine_id添加索引，
以减少物理读。
EXEC #402965288:c=4461629,e=20695435,p=813819,cr=813831,cu=1,mis=0,r=0,dep=0,og=1,plh=3487993498,tim=9176949084157
FETCH #402965288:c=0,e=39,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3487993498,tim=9176949084564
STAT #402965288 id=1 cnt=1 pid=0 pos=1 obj=76192 op='TABLE ACCESS BY INDEX ROWID M_MACHINE_EVENT (cr=813835 pr=813819 pw=0 time=20695423 us cost=3 size=153 card=1)'
STAT #402965288 id=2 cnt=1 pid=1 pos=1 obj=76430 op='INDEX UNIQUE SCAN PK_M_MACHINE_EVENTID (cr=813834 pr=813819 pw=0 time=20695408 us cost=2 size=0 card=1)'
STAT #402965288 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=813831 pr=813819 pw=0 time=20695385 us)'
STAT #402965288 id=4 cnt=390 pid=3 pos=1 obj=76192 op='TABLE ACCESS FULL M_MACHINE_EVENT (cr=813831 pr=813819 pw=0 time=8236 us cost=221307 size=780 card=30)'
FETCH #402965288:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3487993498,tim=9176949085339
*** 2013-12-15 16:39:59.493
CLOSE #402965288:c=0,e=15,dep=0,type=0,tim=9176974078551
=====================
内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理 
相关文章推荐
- 性能测试 数据库优化调试之oracle10046事件跟踪
- Oracle 课程八之性能优化之10046事件
- SQL优化及性能诊断(10046事件/tkprof)
- js 性能优化--事件委托
- 【Android游戏开发十五】关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！
- 15—关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记
- 【性能优化】 之 几种常见的等待事件的演示示例
- 【Android游戏开发十五】关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！
- 【Android游戏开发之路二】关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！
- 【Android游戏开发十五】关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！
- Web前端性能优化——高频触发事件的防抖
- 拜年+散分贴《Oracle SQL_TRACE和10046事件优化SQL实例》
- 关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！
- js性能优化-事件委托
- 前端性能优化：高频执行事件/方法的防抖
- <<Oracle数据库性能优化艺术（第五期）>> 第6周 等待事件
- js性能优化-事件委托
- Oracle优化11-10046事件
- 【Android游戏开发十五】关于Android 游戏开发中 OnTouchEvent() 触屏事件的性能优化笔记！ .
- JS性能优化之事件冒泡