在生産環境中，當資料庫運作異常緩慢的時候，DBA同學們都會想沖進資料庫内部看看sql到底如何運作，為何語句執行的如此緩慢？在我的生産環境中，經常有多表關聯查詢語句運作緩慢，多數是I/O等待的問題，因而我第一步會去看sql的執行計劃是否出現了問題，其次就會用到sql trace工具來跟蹤下sql的實際運作情況！
一：使用sql_trace
1:産生select語句的trace檔案，一般會使用tracefile_identifier給trace檔案起一個辨別性的名稱，便于查找
[oracle@dg53 ~]$ sqlplus /nolog
SQL*Plus: Release 10.2.0.1.0 - Production on Fri Jun 8 11:53:36 2012
Copyright (c) 1982, 2005, Oracle. All rights reserved.
SQL> conn hr/hr
Connected.
SQL> alter session set tracefile_identifier='hr_trace01';
Session altered.
SQL> alter session set sql_trace=true;
SQL> select salary,last_name from employees where employee_id=100;
SALARY LAST_NAME
---------- -------------------------
2000 King
SQL> alter session set sql_trace=false;
[oracle@dg53 ~]$ cd $ORACLE_BASE/admin/orcl10g/udump/
[oracle@dg53 udump]$ ll *hr*
-rw-r----- 1 oracle oinstall 89149 Jun 8 11:58 dg53_ora_10498_hr_trace01.trc
2：使用tkprof工具對産生的trace檔案進行過濾，抽取有用的資訊，預設的trace檔案輸出太多資訊！
sys=no代表不輸出trace檔案中所有sys使用者的操作，包含使用者sql語句引起的遞歸sql，使輸出變的簡潔；
aggragate=yes代表相同的sql語句在輸入檔案中做合并，使輸出變的簡潔；
[oracle@dg53 udump]$ tkprof dg53_ora_10498_hr_trace01.trc /home/oracle/trace01.log aggregate=yes sys=no explain=hr/hr
[oracle@dg53 udump]$ wc -l dg53_ora_10498_hr_trace01.trc
1097 dg53_ora_10498_hr_trace01.trc
[oracle@dg53 udump]$ wc -l /home/oracle/trace01.log
137 /home/oracle/trace01.log
[oracle@dg53 ~]$ cat trace01.log
TKPROF: Release 10.2.0.1.0 - Production on Fri Jun 8 12:06:23 2012
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: dg53_ora_10498_hr_trace01.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
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.01 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
total 1 0.00 0.01 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 (HR)
select salary,last_name
from
employees where employee_id=100
Parse 1 0.00 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 2 2 0 1
total 4 0.00 0.04 2 2 0 1
Misses in library cache during parse: 1 (表示該sql語句執行了硬解析，未在庫緩存中命中)
Optimizer mode: ALL_ROWS (CBO的模式，表示盡可能快的輸出全部的結果集，oltp系統分頁條件下普遍使用first_rows)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=2 pw=0 time=18516 us)
1 INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=1 pw=0 time=11715 us)(object id
51859)
Rows Execution Plan (因為在使用tkprof分析trace檔案的時候使用了explain參數，是以有執行計劃輸出)
0 SELECT STATEMENT MODE: ALL_ROWS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'EMPLOYEES'
(TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_EMP_ID_PK' (INDEX
(UNIQUE))
alter session set sql_trace=false
Parse 1 0.00 0.00 0 0 0 0
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
Parse 2 0.00 0.02 0 0 0 0
Execute 3 0.00 0.01 0 0 0 0
total 7 0.00 0.05 2 2 0 1
Misses in library cache during parse: 2
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
Parse 21 0.01 0.02 0 0 0 0
Execute 122 0.03 0.03 0 0 0 0
Fetch 173 0.01 0.16 18 419 0 633
total 316 0.06 0.22 18 419 0 633
Misses in library cache during parse: 15
Misses in library cache during execute: 15
3 user SQL statements in session.
122 internal SQL statements in session.
125 SQL statements in session.
1 statement EXPLAINed in this session.
Trace file compatibility: 10.01.00
1 session in tracefile.
3 user SQL statements in trace file.
122 internal SQL statements in trace file.
125 SQL statements in trace file.
18 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
HR.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
1097 lines in trace file.
38 elapsed seconds in trace file.
二：10046事件
10046事件按照收集的資訊内容，分為4個級别
level1: 等同于前面介紹的sql_trace
level4: 在level1的基礎上增加綁定變量的收集
level8: 在level1的基礎上增加等待事件的收集
level12: 等同于level4+level8（是以這個級别用的最普遍）
SQL> alter session set tracefile_identifier='hr_trace02';
SQL> var id number
SQL> exec :id := 200
PL/SQL procedure successfully completed.
SQL> alter session set events '10046 trace name context forever,level 12';
SQL> select salary from employees where employee_id=:id;
SALARY
----------
4400
SQL> alter session set events '10046 trace name context off';
-rw-r----- 1 oracle oinstall 89149 Jun 8 11:58 dg53_ora_10498_hr_trace01.trc
-rw-r----- 1 oracle oinstall 3034 Jun 8 14:28 dg53_ora_18857_hr_trace02.trc
[oracle@dg53 udump]$ tkprof dg53_ora_18857_hr_trace02.trc /home/oracle/trace02.log
sys=no aggregate=yes explain=hr/hr
[oracle@dg53 udump]$ cat /home/oracle/trace02.log （tkprof處理後将看不到綁定變量資訊）
TKPROF: Release 10.2.0.1.0 - Production on Fri Jun 8 14:31:46 2012
Trace file: dg53_ora_18857_hr_trace02.trc
alter session set events '10046 trace name context forever,level 12'
total 1 0.00 0.00 0 0 0 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
select salary
employees where employee_id=:id
Fetch 2 0.00 0.01 1 2 0 1
total 4 0.00 0.01 1 2 0 1
1 TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=1 pw=0 time=16216 us)
1 INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=128 us)(object id 51859)
Rows Execution Plan
SQL*Net message to client 2 0.00 0.00
db file sequential read 1 0.01 0.01
SQL*Net message from client 2 0.00 0.00
********************************************************************************
alter session set events '10046 trace name context off'
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
total 7 0.00 0.01 1 2 0 1
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 10.32 15.71
db file sequential read 1 0.01 0.01
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
Execute 0 0.00 0.00 0 0 0 0
total 0 0.00 0.00 0 0 0 0
0 internal SQL statements in session.
3 SQL statements in session.
0 session in tracefile.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
46 lines in trace file.
15 elapsed seconds in trace file.
[oracle@dg53 udump]$ head -30 dg53_ora_18857_hr_trace02.trc
/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc
*** TRACE DUMP CONTINUED FROM FILE
/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc ***
*** 2012-06-08 14:28:26.627
=====================
PARSING IN CURSOR #2 len=68 dep=0 uid=55 oct=42 lid=55 tim=1307750885378875
hv=2804619552 ad='2349fc80'
END OF STMT
EXEC #2:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750885378870
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0
obj#=-1 tim=1307750885378967
WAIT #2: nam='SQL*Net message from client' ela= 126 driver id=1650815232 #bytes=1 p3=0
obj#=-1 tim=1307750885379118
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0
obj#=-1 tim=1307750885379173
WAIT #0: nam='SQL*Net message from client' ela= 5384831 driver id=1650815232 #bytes=1
p3=0 obj#=-1 tim=1307750890764022
PARSING IN CURSOR #3 len=50 dep=0 uid=55 oct=3 lid=55 tim=1307750890764197 hv=2273608758 ad='2349fa44'
select salary from employees where employee_id=:id
PARSE #3:c=0,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764193
BINDS #3:
kkscoacd
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=b7fb9ad0 bln=22 avl=02 flg=05
value=200
EXEC #3:c=0,e=334,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764600
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1307750890764630
WAIT #3: nam='db file sequential read' ela= 13073 file#=5 block#=84 blocks=1 obj#=51857 tim=1307750890780678
FETCH #3:c=5999,e=16119,p=1,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=1307750890780769
三：其他使用者的會話進行跟蹤
1：針對其他使用者的sql_trace跟蹤
C:\>sqlplus hr/[email protected]:1521/dg53.yang.com
SQL*Plus: Release 11.2.0.3.0 Production on Fri Jun 8 14:46:33 2012
Copyright (c) 1982, 2011, Oracle. All rights reserved.
Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
SQL> show user;
USER is "HR"
USER is "SYS"
SQL> select sid,serial# from v$session where username='HR';
SID SERIAL#
---------- ----------
129 55
SQL> select p.spid from v$session s,v$process p where s.paddr=p.addr and s.sid=129 and
s.serial#=55;
SPID
------------
20844
SQL> exec dbms_system.set_sql_trace_in_session(129,55,true);
SQL> select distinct department_id from departments;
DEPARTMENT_ID
-------------
10
20
30
40
SQL> exec dbms_system.set_sql_trace_in_session(129,55,false);
[oracle@dg53 udump]$ tkprof dg53_ora_20844.trc /home/oracle/trace03.log sys=no
aggregate=yes explain=hr/hr
2：針對其他會話的10046事件的開啟和關閉
SQL> exec dbms_monitor.session_trace_enable(129,55,waits=>true,binds=>true);
SQL> exec dbms_monitor.session_trace_disable(129,55);
PL/SQL procedure successfully completed
本文以《讓oracle跑的更快》為指導，如有雷同，不勝榮幸！
本文轉自斬月部落格51CTO部落格，原文連結http://blog.51cto.com/ylw6006/895017如需轉載請自行聯系原作者
ylw6006
![龍珠訓練營task04[圖]](data:image/gif;base64,R0lGODlhAQABAIAAAP///wAAACwAAAAAAQABAAACAkQBADs=)