【性能优化】 之10046 事件
生活随笔
收集整理的這篇文章主要介紹了
【性能优化】 之10046 事件
小編覺得挺不錯的,現在分享給大家,幫大家做個參考.
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
=====================
總結
以上是生活随笔為你收集整理的【性能优化】 之10046 事件的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 【性能优化】 之 变量邦定
- 下一篇： 【性能优化】 之 10053 事件