【SQL_TRACE】SQL優化及效能診斷好幫手
SQL_TRACE作為SQL優化的工具的特點是：她可以對整個當前session或者其他特定的session做全面的跟蹤，以便發現session中出現的異常現象，第一時間處理之。
當然，針對一條SQL的跟蹤同樣有效，類似Explain Plan和AUTOTRACE。
這裡演示一下對當前session進行跟蹤的情況。
1.開啟sql_trace
sec@ora10g> alter session set sql_trace = true;
Session altered.
2.執行待跟蹤的SQL語句
sec@ora10g> select count(*) from t;
COUNT(*)
----------
3000001
3.關閉sql_trace，停止跟蹤
sec@ora10g> alter session set sql_trace = false;
Session altered.
4.確認一下當前執行的sqlplus的spid，以便下一步驟確定生成的trace檔案
sec@ora10g> select spid from V$session s,v$process p,v$mystat m where s.paddr = p.addr and s.sid = m.sid and m.statistic# = 0;
SPID
------------
28863
5.進入到使用者轉儲區udump目錄，sql_trace生成的trace檔案就在這個資料夾中生成
ora10g@secDB /home/oracle$ cd $ORACLE_BASE/admin/$ORACLE_SID/udump
6.使用第4步驟得到的spid得到對應的trace檔案
$ ls -l | grep 28863
-rw-r----- 1 oracle oinstall 2.4K Sep 26 16:12 ora10g_ora_28863.trc
7.檢視一下原汁原味的trace檔案，細心查詢一下上面我們執行過的三個SQL語句。有點亂，這時tkprof工具就派上用場了
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.trc
/oracle/app/oracle/admin/ora10g/udump/ora10g_ora_28863.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining Scoring Engine options
ORACLE_HOME = /oracle/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: asdlabdb01
Release: 2.6.18-128.el5
Version: #1 SMP Wed Dec 17 11:41:38 EST 2008
Machine: x86_64
Instance name: ora10g
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 28863, image: oracle@asdlabdb01 (TNS V1-V3)
*** 2009-09-26 16:12:16.005
*** ACTION NAME:() 2009-09-26 16:12:16.005
*** MODULE NAME:(SQL*Plus) 2009-09-26 16:12:16.005
*** SERVICE NAME:(SYS$USERS) 2009-09-26 16:12:16.005
*** SESSION ID:(525.2176) 2009-09-26 16:12:16.005
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563218755381 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563218755376
EXEC #3:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563218755807
=====================
PARSING IN CURSOR #2 len=22 dep=0 uid=30 ct=3 lid=30 tim=1224563222976558 hv=2763161912 ad='ccd964b0'
select count(*) from t
END OF STMT
PARSE #2:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976554
EXEC #2:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976654
FETCH #2:c=540917,e=527837,p=0,cr=37988,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223504525
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563223504782
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563223505075 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563223505071
EXEC #3:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223505269
STAT #2 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)'
STAT #2 id=2 cnt=3000001 pid=1 pos=1 bj=12662 p='TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)'
=====================
PARSING IN CURSOR #2 len=35 dep=0 uid=30 ct=42 lid=30 tim=1224563232033798 hv=310044142 ad='0'
alter session set sql_trace = false
END OF STMT
PARSE #2:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033795
EXEC #2:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033856
8.使用tkprof工具對上面的trace檔案格式化後，SQL執行的統計資訊盡收眼底。
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_28863.trc ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_28863.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
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 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
********************************************************************************
select count(*)
from
t
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.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.54 0.52 0 37988 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)
3000001 TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)
********************************************************************************
alter session set sql_trace = false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 30
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 2
Fetch 2 0.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.54 0.52 0 37988 0 3
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
4 user SQL statements in session.
0 internal SQL statements in session.
4 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_28863.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
4 user SQL statements in trace file.
0 internal SQL statements in trace file.
4 SQL statements in trace file.
3 unique SQL statements in trace file.
47 lines in trace file.
13 elapsed seconds in trace file.
-- The End --
當然，針對一條SQL的跟蹤同樣有效，類似Explain Plan和AUTOTRACE。
這裡演示一下對當前session進行跟蹤的情況。
1.開啟sql_trace
sec@ora10g> alter session set sql_trace = true;
Session altered.
2.執行待跟蹤的SQL語句
sec@ora10g> select count(*) from t;
COUNT(*)
----------
3000001
3.關閉sql_trace，停止跟蹤
sec@ora10g> alter session set sql_trace = false;
Session altered.
4.確認一下當前執行的sqlplus的spid，以便下一步驟確定生成的trace檔案
sec@ora10g> select spid from V$session s,v$process p,v$mystat m where s.paddr = p.addr and s.sid = m.sid and m.statistic# = 0;
SPID
------------
28863
5.進入到使用者轉儲區udump目錄，sql_trace生成的trace檔案就在這個資料夾中生成
ora10g@secDB /home/oracle$ cd $ORACLE_BASE/admin/$ORACLE_SID/udump
6.使用第4步驟得到的spid得到對應的trace檔案
$ ls -l | grep 28863
-rw-r----- 1 oracle oinstall 2.4K Sep 26 16:12 ora10g_ora_28863.trc
7.檢視一下原汁原味的trace檔案，細心查詢一下上面我們執行過的三個SQL語句。有點亂，這時tkprof工具就派上用場了
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.trc
/oracle/app/oracle/admin/ora10g/udump/ora10g_ora_28863.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining Scoring Engine options
ORACLE_HOME = /oracle/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: asdlabdb01
Release: 2.6.18-128.el5
Version: #1 SMP Wed Dec 17 11:41:38 EST 2008
Machine: x86_64
Instance name: ora10g
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 28863, image: oracle@asdlabdb01 (TNS V1-V3)
*** 2009-09-26 16:12:16.005
*** ACTION NAME:() 2009-09-26 16:12:16.005
*** MODULE NAME:(SQL*Plus) 2009-09-26 16:12:16.005
*** SERVICE NAME:(SYS$USERS) 2009-09-26 16:12:16.005
*** SESSION ID:(525.2176) 2009-09-26 16:12:16.005
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563218755381 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563218755376
EXEC #3:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563218755807
=====================
PARSING IN CURSOR #2 len=22 dep=0 uid=30 ct=3 lid=30 tim=1224563222976558 hv=2763161912 ad='ccd964b0'
select count(*) from t
END OF STMT
PARSE #2:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976554
EXEC #2:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563222976654
FETCH #2:c=540917,e=527837,p=0,cr=37988,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223504525
FETCH #2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563223504782
=====================
PARSING IN CURSOR #3 len=52 dep=0 uid=30 ct=47 lid=30 tim=1224563223505075 hv=1029988163 ad='dea6cf90'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #3:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1224563223505071
EXEC #3:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1224563223505269
STAT #2 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)'
STAT #2 id=2 cnt=3000001 pid=1 pos=1 bj=12662 p='TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)'
=====================
PARSING IN CURSOR #2 len=35 dep=0 uid=30 ct=42 lid=30 tim=1224563232033798 hv=310044142 ad='0'
alter session set sql_trace = false
END OF STMT
PARSE #2:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033795
EXEC #2:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1224563232033856
8.使用tkprof工具對上面的trace檔案格式化後，SQL執行的統計資訊盡收眼底。
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_28863.trc ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_28863.out
TKPROF: Release 10.2.0.3.0 - Production on Sat Sep 26 16:15:18 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_28863.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
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 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
********************************************************************************
select count(*)
from
t
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.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.54 0.52 0 37988 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 30
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=37988 pr=0 pw=0 time=527843 us)
3000001 TABLE ACCESS FULL T (cr=37988 pr=0 pw=0 time=3000085 us)
********************************************************************************
alter session set sql_trace = false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Parsing user id: 30
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 2
Fetch 2 0.54 0.52 0 37988 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.54 0.52 0 37988 0 3
Misses in library cache during parse: 0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
4 user SQL statements in session.
0 internal SQL statements in session.
4 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_28863.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
4 user SQL statements in trace file.
0 internal SQL statements in trace file.
4 SQL statements in trace file.
3 unique SQL statements in trace file.
47 lines in trace file.
13 elapsed seconds in trace file.
-- The End --
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/519536/viewspace-616240/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- Oracle診斷案例-Sql_traceOracleSQL
- 使用SQL_TRACE進行資料庫診斷SQL資料庫
- 直播分享| 騰訊雲 MongoDB 智慧診斷及效能優化實踐MongoDB優化
- 使用SQL_TRACE進行資料庫診斷(轉)SQL資料庫
- 使用SQL_TRACE進行資料庫診斷(1)SQL資料庫
- 使用SQL_TRACE進行資料庫診斷(2)SQL資料庫
- 使用SQL_TRACE進行資料庫診斷（zt）SQL資料庫
- 《深入解析Oracle》第十章，效能診斷與SQL優化OracleSQL優化
- 案例 - EBS SQL效能診斷SQL
- Oracle最強有力的輔助診斷工具SQL_TRACEOracleSQL
- 轉載：使用SQL_TRACE進行資料庫診斷SQL資料庫
- 使用SQL_TRACE進行資料庫診斷(轉載)SQL資料庫
- Part II 診斷和優化資料庫效能優化資料庫
- Spark效能優化：診斷記憶體的消耗Spark優化記憶體
- oracle 效能診斷藝術優化一書到手Oracle優化
- MySQL效能診斷與調優MySql
- 【DB】使用SQL_TRACE進行資料庫診斷跟蹤SQL資料庫
- 使用SQL_TRACE /10046進行資料庫診斷SQL資料庫
- 熊貓大俠一次效能診斷優化十一問優化
- 如何收集用來診斷效能問題的10046 Trace(SQL_TRACE) (文件 ID 1523462.1)SQL
- Oracle SQLT 診斷SQL語句效能(3)OracleSQL
- Oracle SQLT 診斷SQL語句效能(2)OracleSQL
- Oracle SQLT 診斷SQL語句效能(1)OracleSQL
- 某公司oracle 效能調優診斷案例Oracle
- Sql最佳化(十九) 調優工具（2）sql_traceSQL
- Oracle效能優化視訊學習筆記－診斷和調優工具Oracle優化筆記
- sql_trace 及 tkprof 工具SQL
- sql效能優化SQL優化
- sql 效能優化SQL優化
- 幫朋友優化個sql優化SQL
- 效能優化案例-SQL優化優化SQL
- TiDB 查詢優化及調優系列（三）慢查詢診斷監控及排查TiDB優化
- oracle 效能診斷工具Oracle
- MySQL 效能優化之SQL優化MySql優化
- SQL問題診斷SQL
- SQL效能優化技巧SQL優化
- Sql效能優化梳理SQL優化
- Oracle SQL效能優化OracleSQL優化