Oracle 課程八之性能優化之Oracle SQL Trace


一. SQL_TRACE

  當SQL語句出現性能問題時,我們可以用SQL_TRACE來跟蹤SQL的執行情況,通過跟蹤,我們可以了解一條SQL或者PL/SQL包的運行情況,SQL_TRACE命令會將SQL執行的整個過程輸出到一個trace文件中,我們可以讀這個trace 文件來了解在這個SQL執行過程中Oracle 都做了哪些操作:

a.SQL是如何操作數據的。
b.SQL執行過程中產生了那些等待時間。
c.SQL執行中消耗了多少資源。
d.SQL的實際執行計划。
e.SQL產生的遞歸語句。

可以通過sql命令啟動SQL_TRACE,或者在初始化參數里面。

 

SQL>alter session set sql_trace=true;

或者

SQL> alter database set sql_trace=true;

  這兩條命令的區別:

  在session級別設置,只對當前session進行跟蹤,在實例級別,會對實例上所有的SQL做跟蹤,這種方式跟蹤的SQL太多,代價是非常大的,所有很少用。如果是在初始化文件里面設置,只需要在參數文件里添加一個sql_trace 參數即可。

示例:

1.確定當前的trace文件。

1.1   通過設置trace 文件標識

SQL> alter session set tracefile_identifier='TEST_TRACE';

會話已更改。

  設置標識的目的就是方便我們查找生成的trace文件。我們只需要在trace目錄查找文件名里帶有標識的文件即可。
在Oracle 10g中,SQL_TRACE生成的trace文件默認路勁是$ORACLE_BASE/admin/SID/udump. 
在Oracle 11g,trace 默認路徑在:$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目錄下. 

1.2直接用如下SQL直接查出,當前的trace文件名。

SELECT      d.VALUE

         || '/'

         || LOWER (RTRIM (i.INSTANCE, CHR (0)))

         || '_ora_'

         || p.spid

         || '.trc'

            AS "trace_file_name"

  FROM   (SELECT   p.spid

            FROM   v$mystat m, v$session s, v$process p

           WHERE   m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

         (SELECT   t.INSTANCE

            FROM   v$thread t, v$parameter v

           WHERE   v.NAME = 'thread'

                   AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

         (SELECT   VALUE

            FROM   v$parameter

           WHERE   NAME = 'user_dump_dest') d;

 

SQL> SELECT    d.VALUE

  2        || '/'

  3        || LOWER (RTRIM (i.INSTANCE, CHR (0)))

  4        || '_ora_'

  5        || p.spid

  6        || '.trc' as "trace_file_name"

  7    FROM (SELECT p.spid

  8            FROM v$mystat m, v$session s, v$process p

  9          WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

 10        (SELECT t.INSTANCE

 11            FROM v$thread t, v$parameter v

 12          WHERE v.NAME = 'thread'

 13            AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

 14        (SELECT VALUE

 15            FROM v$parameter

 16          WHERE NAME = 'user_dump_dest') d;

 

trace_file_name

--------------------------------------------------------------------------------

d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048.trc
查義當前Trace文件

 

2.啟動SQL_TRACE

SQL> alter session set sql_trace=true;

會話已更改。

3.進行相關事務操作

SQL> select * from t;

4.關閉SQL_TRACE

SQL> alter session set sql_trace=false;

會話已更改。

注意,這里是顯示的關閉SQL_TRACE,在session級別,也可以直接退出SQLPLUS來終止SQL_TRACE。

二. TKPROF的使用簡介

  Tkprof是一個用於分析Oracle跟蹤文件並且產生一個更加清晰合理的輸出結果的可執行工具。如果一個系統的執行效率比較低,一個比較好的方法是通過跟蹤用戶的會話並且使用Tkprof工具使用排序功能格式化輸出,從而找出有問題的SQL語句。

TKPROF  filename1, filename2 [ SORT  = [ opion][,option] ]
  [  PRINT = integer ]
  [ AGGREGATE  = [ YES | NO ] ]
  [ INSERT = filename3 ]
  [ SYS = [ YES | NO ]  ]
  [  [ TABLE = schema.table ] | [ EXPLAIN = user/password ]  ]
  [  RECORD = filename ]
TKPROF 命令語法

 

filename1  指定的輸入文件,可以是多個文件聯起來。
Filename2  格式化輸出文件。
SORT     在輸出到輸出文件前,先進程排序。如果省去,則按照實際使用的順序輸出到文件中。排序選項有以下多種:

  prscnt  number of times parse was called
  prscpu  cpu time parsing
  prsela  elapsed time parsing
  prsdsk  number of disk reads during parse
  prsqry  number of buffers for consistent read during parse
  prscu   number of buffers for current read during parse
  prsmis  number of misses in library cache during parse
  execnt  number of execute was called
  execpu  cpu time spent executing
  exeela  elapsed time executing
  exedsk  number of disk reads during execute
  exeqry  number of buffers for consistent read during execute
  execu   number of buffers for current read during execute
  exerow  number of rows processed during execute
  exemis  number of library cache misses during execute
  fchcnt  number of times fetch was called
  fchcpu  cpu time spent fetching
  fchela  elapsed time fetching
  fchdsk  number of disk reads during fetch
  fchqry  number of buffers for consistent read during fetch
  fchcu   number of buffers for current read during fetch
  fchrow  number of rows fetched
  userid  userid of user that parsed the cursor
SORT選項

PRINT        只列出輸出文件的第一個integer 的SQL語句。默認為所有的SQL語句。
AGGREGATE    如果= NO ,則不對多個相同的SQL進行匯總。
INSERT       SQL 語句的一種,用於將跟蹤文件的統計信息存儲到數據庫中。在TKPROF創建腳本后,在將結果輸入到數據庫中。
SYS         禁止或啟用 將SYS用戶所發布的SQL語句列表到輸出文件中。
TABLE       在輸出到輸出文件前,用於存放臨時表的用戶名和表名。
EXPLAIN     對每條SQL 語句確定其執行規划。並將執行規划寫到輸出文件中。
其中比較有用的一個排序選項是fchela,即按照elapsed time fetching來對分析的結果排序(記住要設置初始化參數timed_statistics=true),生成的文件將把最消耗時間的sql放在最前面顯示。另外一個有用的參數就是sys,這個參數設置為no可以阻止所有以sys用戶執行的sql被顯示出來,這樣可以減少分析出來的文件的復雜度,便於查看。

對Tkprof命令輸出的解釋:
  首先解釋輸出文件中列的含義:
CALL:每次SQL語句的處理都分成三個部分
Parse:這步將SQL語句轉換成執行計划,包括檢查是否有正確的授權和所需要用到的表、列以及其他引用到的對象是否存在。
Execute:這步是真正的由Oracle來執行語句。對於insert、update、delete操作,這步會修改數據,對於select操作,這步就只是確定選擇的記錄。
Fetch:返回查詢語句中所獲得的記錄,這步只有select語句會被執行。
COUNT:這個語句被parse、execute、fetch的次數。
CPU:這個語句對於所有的parse、execute、fetch所消耗的cpu的時間,以秒為單位。
ELAPSED:這個語句所有消耗在parse、execute、fetch的總的時間。
DISK:從磁盤上的數據文件中物理讀取的塊的數量。一般來說更想知道的是正在從緩存中讀取的數據而不是從磁盤上讀取的數據。
QUERY:在一致性讀模式下,所有parse、execute、fetch所獲得的buffer的數量。一致性模式的buffer是用於給一個長時間運行的事務提供一個一致性讀的快照,緩存實際上在頭部存儲了狀態。
CURRENT:在current模式下所獲得的buffer的數量。一般在current模式下執行insert、update、delete操作都會獲取buffer。在current模式下如果在高速緩存區發現有新的緩存足夠給當前的事務使用,則這些buffer都會被讀入了緩存區中。
ROWS: 所有SQL語句返回的記錄數目,但是不包括子查詢中返回的記錄數目。對於select語句,返回記錄是在fetch這步,對於insert、update、delete操作,返回記錄則是在execute這步。


Tkprof的使用步驟基本上遵循以下幾步:
1、設置TIMED_STATISTICS為True,可以在會話級別,也可以在實例級別。

會話級:
SQL> alter session set timed_statistics=True;
實例級:
SQL> alter system set timed_statistics=True scope=both;
設置TIMED_STATISTICS

2、 設置SQL_TRACE,可以在會話級,也可以在數據庫級。

會話級:
SQL> alter session set sql_trace=true;
或者:
SQL>EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);
實例級:
SQL> alter system set sql_trace=true scope=both;
設置SQL_TRACE

下面兩個例子說明一下具體的用法:

SQL> create table testlib  as select object_name noindex,object_name idx from dba_objects;

表已創建。
                                                                                                                                                                                 
SQL> alter session set timed_statistics=true;

會話已更改。
設置Timed_statistics
SQL> alter session set sql_trace=true;

會話已更改。

SQL> select count(*) from testlib;

  COUNT(*)                                                                     
----------                                                                     
     69304   

SQL> alter session set sql_trace= false;

會話已更改。
用戶級跟蹤

或DBA跟蹤:(例如sys跟蹤test,需要用sysdba登錄

SQL> select username,sid,serial# from v$session where username='system';
USERNAME                              SID    SERIAL#
------------------------------ ---------- ----------
GDSBDW                                 37      27544

SQL>exec sys.dbms_system.set_sql_trace_in_session(37,27544,true);

SQL>exec sys.dbms_system.set_sql_trace_in_session(37,27544,false);
DBA級跟蹤

3.查詢跟蹤文件位置:

SQL> select 'dss_ora_'||spid||'.trc' from v$process where addr = (select paddr f
rom v$session where sid=37);
'DSS_ORA_'||SPID||'.TRC'
------------------------
orcl_ora_3040.trc
查詢跟蹤文件位置

也可以用下面的sql語句獲得trace文件的所在位置

 SQL>  select
  2  d.value||'/'||lower(rtrim(i.instance,chr(0)))||'_ora_'||p.spid||'.trc' trace_file_name
  3  from
  4  (select p.spid
  5  from sys.v$mystat m, sys.v$session s,sys.v$process p
  6  where m.statistic#=1 and s.sid=m.sid and p.addr=s.paddr) p,
  7  (select
  8  t.instance from sys.v$thread t,sys.v$parameter v
  9  where v.name ='thread' and (v.value =0 or t.thread#= to_number(v.value))) i,
 10* (select value from sys.v$parameter where name ='user_dump_dest') d

 
TRACE_FILE_NAME                                                                
--------------------------------------------------------------------------------
f:\app\administrator\diag\rdbms\orcl\orcl\trace/orcl_ora_3040.trc 
查詢跟蹤文件位置

    
4.使用tkprof分析trace文件

explain=user/password

  在trace文件中輸入SQL的執行計划,需要注意的是,如果不使用explain,在trace 文件中我們看到的是SQL實際的執行路勁。 如果使用了explain,tkprof在trace文件中不但輸入SQL的實際執行路徑,還會生成該SQL的執行計划。

sys=no

  如果設置為yes,在trace 文件中將輸入所有的SYS用戶的操作,也包含用戶SQL語句引發的遞歸SQL。
  如果為no,則不輸出這些信息。
  不過默認情況下是yes,實際上設置為no后,trace文件具有更佳的可讀性,因此一般在用tkprof工具時都手工的把該參數設置為no。

aggregate=yes|no

     默認情況下,tkprof工具將所有相同的SQL在輸入文件中做合並,如果設置為no,則分別列出每個SQL的信息。一般合並后看起來比較簡潔,如果需要查看每一個SQL單獨的信息,可以把aggregate設置為no。

C:\Documents and Settings\Administrator>tkprof  f:\app\administrator\diag\rdbms\orcl\orcl\trace/orcl_ora_4020.trc   f:\4020.trc.txt  aggregate=yes sys=no waits=yes sort=fchela
Tkprof分析Trace文件

tkprocf輸出了以下文件:f:\4020.trc.txt

TKPROF: Release 11.1.0.6.0 - Production on 星期一 3月 29 13:50:42 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: f:\4020.trc
Sort options: fchela 
********************************************************************************
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 

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        6      0.01    5403.67          0          1          0           0
Execute      7      0.00       0.00          0          0          0           0
Fetch        8      0.03       0.07        137       2080          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       21      0.04    5403.75        137       2081          0           4

Misses in library cache during parse: 2
Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.05          0          0          0           0
Execute      2      0.00       0.01          0          0          0           0
Fetch        2      0.00       0.08        379         67          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.15        379         67          0           1

Misses in library cache during parse: 2
Misses in library cache during execute: 1

    7  user  SQL statements in session.
    2  internal SQL statements in session.
    9  SQL statements in session.
********************************************************************************
Trace file: f:\4020.trc
Trace file compatibility: 11.01.00
Sort options: fchela 
       1  session in tracefile.
       7  user  SQL statements in trace file.
       2  internal SQL statements in trace file.
       9  SQL statements in trace file.
       6  unique SQL statements in trace file.
     107  lines in trace file.
     124  elapsed seconds in trace file.
Tkprof分析Trace文件結果:

5.分析結果關鍵字解釋

PARSING IN CURSOR 部分:    
                Len: 被解析SQL的長度
                Dep: 產生遞歸SQL的深度
                Uid:user id
                    Otc: Oracle command type 命令的類型
                Lid: 私有用戶id
                Tim:時間戳
                Hv: hash value
                    Ad:SQL address

PARSE,EXEC,FETCH 部分
                C: 消耗的CPU time
                E:elapsed time 操作的用時
                P: physical reads 物理讀的次數
                Cr: consistent reads 一致性方式讀取的數據塊
                Cu:current 方式讀取的數據塊
                Mis:cursor misss in cache 硬分析次數
                R: -rows 處理的行數
                Dep: depth 遞歸SQL的深度
                Og: optimizer goal 優化器模式
                Tim:timestamp時間戳

STATS 部分:
                Id: 執行計划的行源號
                Cnt:當前行源返回的行數
                Pid:當前行源號的父號
                Pos:執行計划中的位置
                Obj:當前操作的對象id(如果當前行原始一個對象的話)
                Op:當前行源的數據訪問操作
分析結果及關鍵字解釋

  我們來看剛才生成的trace文件,頭部信息描述了tkprof 的版本以及報告中一些列的含義,對於任何一條sql語句,都應該包含Parse—sql分析階段,Execute—sql執行階段,Fetch—數據提取階段,橫向的列如圖所示,包含消耗cpu時間0.00秒,操作總耗時0.04秒,物理讀取了0個數據塊,沒有發生current方式的讀取(一般在update會發生),一共提取記錄1條。
Misses in library cache during parse: 2表示這是2次硬分析(表示shared pool 中2次沒有命中,軟解析為0,硬解析為2)
Misses in library cache during execute: 1表示這是1次硬分析(表示獲得了SQL Hander,但是執行時在SQL區沒有找到或被覆蓋,導致硬解析)
Optimizer mode: ALL_ROWS表示oracle的優化器模式為ALL_ROWS。

  下面是sql執行的具體計划,可以看到執行計划選擇的是全表掃描。
經過處理以后的trace文件的確比較容易看明白,它有助於我們分析sql的性能問題。
下面我通過一個trace實例來解釋一下,為什么OLTP系統中需要變量綁定機制。
  當用戶和數據庫建立連接,並發送一條sql語句以后,oracle會對該sql進行hash函數運算(hash算法提供了一種快速存取數據的方法,它用一種算法建立鍵值與真實值之間的對應關系,每一個真實值只能有一個鍵值,但是一個鍵值可以對應多個真實值,以方便存取),得到一個hash值,然后到共享池中尋找是否有匹配的hash值的sql存在;如果有,就直接使用該sql的執行計划去執行sql。如果沒有,oracle就會認為這是一條新的sql語句,然后按照語法分析,語義分析,生成執行計划,執行sql這些步驟來執行最終把結果返回給用戶。

  這些步驟也被成為硬分析,可以想象,如果減少硬分析,能夠大大降低數據庫花費在sql解析上的資源開銷。

  我們先執行一條sql 1000次,比較綁定變量和不綁定變量的差異。得到結果以后,要計算實際的消耗,我們需要把OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS以及OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS的時間累計起來,前者表示數據字典表的相關的信息,包含權限控制等,后者表示sql所衍生出的遞歸sql語句的信息。可以看到綁定變量的,整條語句執行時間為0.22+0.02=0.24秒,CPU時間0.18+0.03=0.21秒,分析次數3次,執行次數1003次。而不綁定變量的時候,整條語句執行時間為0.28+1.29=1.57秒,CPU時間0.31+1.26=1.57秒,分析次數1002次,執行次數1003次。可見綁定變量的確能夠帶來更低的開銷。(如何設計數據庫中使用綁定變量也是和系統息息相關的,很多數據庫問題都是在設計以后就已經存在的)


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM