如何使用AWR報告來診斷資料庫效能問題

dbasdk發表於2014-09-04
資料庫

如何主動避免問題發生及做好診斷資訊的收集

有些問題是無法預見的，但大部分其它的問題如果及早發現一些徵兆其實是可以避免的。同時，如果問題確實發生了，那麼收集問題發生時的資訊就非常重要。有關於如何主動避免問題及診斷資訊的收集.
對於資料庫整體的效能問題，AWR的報告是一個非常有用的診斷工具。
一般來說，當檢測到效能問題時，我們會收集覆蓋了發生問題的時間段的AWR報告-但是最好只收集覆蓋1個小時時間段的AWR報告-如果時間過長，那麼AWR報告就不能很好的反映出問題所在。還應該收集一份沒有效能問題的時間段的AWR報告，作為一個參照物來對比有問題的時間段的AWR報告。這兩個AWR報告的時間段應該是一致的，比如都是半個小時的，或者都是一個小時的。 

Interpretation

在處理效能問題時，我們最關注的是資料庫正在等待什麼。
當程式因為某些原因不能進行操作時，它需要等待。花費時間最多的等待事件是我們最需要關注的，因為降低它，我們能夠獲得最大的好處。
AWR報告中的"Top 5 Timed Events"部分就提供了這樣的資訊，可以讓我們只關注主要的問題。

  • Top 5 Timed Events

    正如前面提到的，"Top 5 Timed Events"是AWR報告中最重要的部分。它指出了資料庫的sessions花費時間最多的等待事件，如下：
    Top 5 Timed Events                                         Avg %Total

~~~~~~~~~~~~~~~~~~                                        wait   Call

Event                                 Waits    Time (s)   (ms)   Time Wait Class

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

db file scattered read           10,152,564      81,327      8   29.6   User I/O

db file sequential read          10,327,231      75,878      7   27.6   User I/O

CPU time                                         56,207          20.5

read by other session             4,397,330      33,455      8   12.2   User I/O

PX Deq Credit: send blkd             31,398      26,576    846    9.7      Other

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


    Top 5 Events部分包含了一些跟Events（事件）相關的資訊。它記錄了這期間遇到的等待的總次數，等待所花費的總時間，每次等待的平均時間；這一部分是按照每個Event佔總體call time的百分比來進行排序的。

    根 據Top 5 Events部分的資訊的不同，接下來我們需要檢查AWR報告的其他部分，來驗證發現的問題或者做定量分析。等待事件需要根據報告期的持續時間和當時資料 庫中的併發使用者數進行評估。如：10分鐘內1000萬次的等待事件比10個小時內的1000萬等待更有問題；10個使用者引起的1000萬次的等待事件比 10,000個使用者引起的相同的等待要更有問題。

    就像上面的例子，將近60%的時間是在等待IO相關的事件。

    • 事件"db file scattered read"一般表明正在做由全表掃描或者index fast full scan引起的多塊讀。
    • 事件"db file sequential read"一般是由不能做多塊讀的操作引起的單塊讀（如讀索引）

    其他20%的時間是花在使用或等待CPU time上。過高的CPU使用經常是效能不佳的SQL引起的（或者這些SQL有可能用更少的資源完成同樣的操作）；對於這樣的SQL，過多的IO操作也是一個症狀。關於CPU使用方面，我們會在之後討論。

    在以上基礎上，我們將調查是否這個等待事件是有問題的。若有問題，解決它；若是正常的，檢查下個等待事件。

    過多的IO相關的等待一般會有兩個主要的原因：

    • 資料庫做了太多的讀操作
    • 每次的IO讀操作都很慢
    Top 5 Events部分的顯示的資訊會幫助我們檢查：

    • 是否資料庫做了大量的讀操作：
      上面的圖顯示了在這段時間裡兩類讀操作都分別大於1000萬，這些操作是否過多取決於報告的時間是1小時或1分鐘。我們可以檢查AWR報告的elapsed time如果這些讀操作確實是太多了，接下來我們需要檢查AWR報告中 SQL Statistics 部分的資訊，因為讀操作都是由SQL語句發起的。
    • 是否是每次的IO讀操作都很慢：
      上面的圖顯示了在這段時間裡兩類讀操作平均的等待時間是小於8ms的
      至於8ms是快還是慢取決於底層的硬體裝置；一般來講小於20ms的都可以認為是可以接受的。

      我們還可以在AWR報告"Tablespace IO Stats"部分得到更詳細的資訊
      Tablespace IO Stats                       DB/Inst: VMWREP/VMWREP  Snaps: 1-15

-> ordered by IOs (Reads + Writes) desc



Tablespace

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

                Av      Av     Av                       Av     Buffer Av Buf

        Reads Reads/s Rd(ms) Blks/Rd       Writes Writes/s      Waits Wt(ms)

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

TS_TX_DATA

   14,246,367     283    7.6     4.6  145,263,880    2,883  3,844,161    8.3

USER

      204,834       4   10.7     1.0   17,849,021      354     15,249    9.8

UNDOTS1

       19,725       0    3.0     1.0   10,064,086      200      1,964    4.9

AE_TS

    4,287,567      85    5.4     6.7          932        0    465,793    3.7

TEMP

    2,022,883      40    0.0     5.8      878,049       17          0    0.0

UNDOTS3

    1,310,493      26    4.6     1.0      941,675       19         43    0.0

TS_TX_IDX

    1,884,478      37    7.3     1.0       23,695        0     73,703    8.3

>SYSAUX

      346,094       7    5.6     3.9      112,744        2          0    0.0

SYSTEM

     101,771       2    7.9     3.5       25,098        0        653    2.7

      如上圖，我們關心Av Rd(ms)的指標。如果它高於20ms並且同時有很多讀操作的，我們可能要開始從OS的角度調查是否有潛在的IO問題。

      注：對於一些比較空閒的tablespace/files,我們可能會得到一個比較大的Av Rd(ms)值；對於這樣的情況，我們應該忽略這樣的tablespace/files;因為這個很大的值可能是由於硬碟自旋(spin)引起的，沒有太大的參考意義。比如對
      於一個有1000萬次讀操作而且很慢的系統，引起問題的基本不可能是一個只有10次read的tablespace/file.
      雖 然高"db file scattered read"和"db file sequential read"等待可以是I / O相關的問題，但是很多時候這些等待也可能是正常的；實際上，對一個已經效能很好的資料庫系統，這些等待事件往往在top 5等待事件裡，因為這意味著您的資料庫沒有那些真正的“問題”。
      訣竅是能夠評估引起這些等待的語句是否使用了最優的訪問路徑。如果"db file scattered read"比較高，那麼相關的SQL語句可能使用了全表掃描而沒有使用索引（也許是沒有建立索引，也許是沒有合適的索引）；相應的，如果"db file sequential read"過多，則表明也許是這些SQL語句使用了selectivity不高的索引從而導致訪問了過多不必要的索引塊或者使用了錯誤的索引。這些等待可 能說明SQL語句的執行計劃不是最優的。
      接下來就需要透過AWR來檢查這些top SQL是否可以進一步的調優，我們可以檢視AWR報告中 SQL Statistics 的部分.
      上面的例子顯示了20%的時間花在了等待或者使用CPU上，我們也需要檢查 SQL statistics 部分來進一步的分析。
    需要注意，接下來的分析步驟取決於我們在TOP 5部分的發現。在上面的例子裡，3個top wait event表明問題可能與SQL語句執行計劃不好有關，所以接下來我們要去分析"SQL Statistics"部分。
    同樣的，因為我們並沒有看到latch相關的等待，latch在我們這個例子裡並沒有引發嚴重的效能問題；那麼我們接下來就完全不需要分析latch相關的資訊。
    一 般來講，如果資料庫效能很慢，TOP 5等待事件裡"CPU"， "db file sequential read" 和"db file scattered read" 比較明顯（不管它們之間的順序如何），我們總是需要檢查Top SQL (by logical and physical reads)部分；呼叫SQL Tuning Advisor或者手工調優這些SQL來確保它們是有效率的執行。

  • SQL Statistics

    AWR包含了一些不同的SQL統計值：
    如何使用AWR報告來診斷資料庫效能問題
    根據Top 5 部分的Top Wait Event不同，我們需要檢查不同的SQL statistic。

    在我們這個例子裡，Top Wait Event是"db file scattered read"，"db file sequential read"和CPU；我們最需要關心的是SQL ordered by CPU Time, Gets and Reads。

    我們會從"SQL ordered by gets"入手，因為引起高buffer gets的SQL語句一般是需要調優的物件。

    SQL ordered by Gets                       

-> Resources reported for PL/SQL code includes the resources used by all SQL

  statements called by the code.

-> Total Buffer Gets:   4,745,943,815

-> Captured SQL account for     122.2% of Total



                               Gets              CPU     Elapsed

 Buffer Gets   Executions    per Exec   %Total Time (s)  Time (s)    SQL Id

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

1,228,753,877          168  7,314,011.2   25.9  8022.46   8404.73 5t1y1nvmwp2

SELECT ADDRESSID",CURRENT$."ADDRESSTYPEID",CURRENT$URRENT$."ADDRESS3",

CURRENT$."CITY",CURRENT$."ZIP",CURRENT$."STATE",CURRENT$."PHONECOUNTRYCODE",

CURRENT$."PHONENUMBER",CURRENT$."PHONEEXTENSION",CURRENT$."FAXCOU



1,039,875,759   62,959,363         16.5   21.9  5320.27   5618.96 grr4mg7ms81


Module: DBMS_SCHEDULER


INSERT INTO "ADDRESS_RDONLY" ("ADDRESSID","ADDRESSTYPEID","CUSTOMERID","
ADDRESS1","ADDRESS2","ADDRESS3","CITY","ZIP","STATE","PHONECOUNTRYCODE","PHONENU

   854,035,223          168  5,083,543.0   18.0  5713.50   7458.95 4at7cbx8hnz

SELECT "CUSTOMERID",CURRENT$."ISACTIVE",CURRENT$."FIRSTNAME",CURRENT$."LASTNAME",CU<
RRENT$."ORGANIZATION",CURRENT$."DATEREGISTERED",CURRENT$."CUSTOMERSTATUSID",CURR
ENT$."LASTMODIFIEDDATE",CURRENT$."SOURCE",CURRENT$."EMPLOYEEDEPT",CURRENT$.

    對這些Top SQL,可以手工調優，也可以呼叫SQL Tuning Advisor。

    分析：

    • -> Total Buffer Gets: 4,745,943,815
      假設這是一個一個小時的AWR報告，4,745,943,815是一個很大的值；所以需要進一步分析這個SQL是否使用了最優的執行計劃
    • Individual Buffer Gets
      上面的例子裡單個的SQL的buffer get非常多，最少的那個都是8億5千萬。這三個SQL指向了兩個不同的引起過多buffers的原因：
      • 單次執行buffer gets過多
        SQL_ID為'5t1y1nvmwp2'和'4at7cbx8hnz'的SQL語句總共被執行了168次，但是每次執行引起的buffer gets超過500萬。這兩個SQL應該是主要的需要調優的候選者。
      • 執行次數過多
        SQL_ID 'grr4mg7ms81' 每次執行只是引起16次buffer gets,減少這條SQL每次執行的buffer get可能並不能顯著減少總共的buffer gets。這條語句的問題是它執行的太頻繁了，6500萬次。
        改變這條SQL的執行次數可能會更有意義。這個SQL看起來是在一個迴圈裡面被呼叫，如果可以讓它一次處理的資料更多也許可以減少它執行的次數。
      注意：對於某些非常繁忙的系統來講，以上的數字可能都是正常的。這時候我們需要把這些數字跟正常時段的數字作對比，如果沒有什麼太大差別，那麼這些SQL並不是引起問題的元兇（雖然透過調優這些SQL我們仍然可以受益）

    Other SQL Statistic Sections

    就像之前提到的那樣，AWR報告中有很多不同的部分用來分析各種不同的問題。如果特定的問題並沒有出現，那麼分析AWR報告的這些部分並不能有很大的幫助。
    下面提到了一些可能的問題：
    • Waits for 'Cursor: mutex/pin' 如 果發現了一些像"Cursor: pin S wait on X" 或"Cursor: mutex X" 類的mutex等待，那麼可能是由於parsing引起的問題。檢查"SQL ordered by Parse Calls" 和"SQL ordered by Version Count"部分的Top SQL，這些SQL可能引起這類的問題。

  • Load Profile

    根據Top 5等待事件的不同，"Load Profile"可以提供一些有用的背景資料或潛在問題的細節資訊。 
    Load Profile

~~~~~~~~~~~~                            Per Second       Per Transaction

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

                 Redo size:          4,585,414.80          3,165,883.14

             Logical reads:             94,185.63             65,028.07

             Block changes:             40,028.57             27,636.71

            Physical reads:              2,206.12              1,523.16

           Physical writes:              3,939.97              2,720.25

                User calls:                 50.08                 34.58

                    Parses:                 26.96                 18.61

               Hard parses:                  1.49                  1.03

                     Sorts:                 18.36                 12.68

                    Logons:                  0.13                  0.09

                  Executes:              4,925.89              3,400.96

              Transactions:                  1.45





 % Blocks changed per Read:   42.50    Recursive Call %:    99.19

Rollback per transaction %:   59.69       Rows per Sort:  1922.64

    在這個例子裡，Top 5 Events部分顯示問題可能跟SQL的執行有關，那麼我們接下來檢查load profile部分。

    如果您檢查AWR report是為了一般性的效能調優，那麼可以看到有比較多的redo activity和比較高的physical writes. Physical writes比physical read要高，並且有42%的塊被更改了.

    此外，hard parse的次數要少於soft parse.
    如果mutex等待事件比較嚴重，如"library cache: mutex X"，那麼檢視所有parse的比率會更有用。

    當然，如果把Load Profile部分跟正常時候的AWR報告做比較會更有用，比如，比較redo size, users calls, 和 parsing這些效能指標。

  • Instance Efficiency

    Instance Efficiency部分更適用於一般性的調優，而不是解決某個具體問題（除非等待事件直接指向這些指標）。

    Instance Efficiency Percentages (Target 100%)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

           Buffer Nowait %:   99.91       Redo NoWait %:  100.00

           Buffer  Hit   %:   98.14    In-memory Sort %:   99.98

           Library Hit   %:   99.91        Soft Parse %:   94.48

        Execute to Parse %:   99.45         Latch Hit %:   99.97

Parse CPU to Parse Elapsd %:   71.23     % Non-Parse CPU:   99.00

    從我們的這個例子來看，最有用的資訊是%Non-Parse CPU，它表明幾乎所有的CPU都消耗在了Execution而不是Parse上，所以調優SQL會對效能有改善。

    94.48％ 的soft parse比率顯示hard parse的比例很小，這是可取的。Execute to Parse %很高，說明cursor被很好的重用了。我們總是期望這裡的值都是接近100%,但是因為應用的不同，如果這個部分的引數的某些值很小，也是可以認為沒 有問題的；如在資料倉儲環境，hard parse因為使用了物化檢視或histogram而變得很高。所以，重要的是，我們需要把這部分資訊和正常時候的AWR報告做比較來判斷是否有問題。

  • Latch Activity

    在我們這個例子裡，我們並沒有看到很高的latch相關的等待，所以這部分的資訊可以忽略。

    但是如果latch相關的等待很嚴重，我們需要檢視Latch Sleep Breakdown 部分sleeps很高的latch



    Latch Sleep Breakdown



   * ordered by misses desc 





Latch Name

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

 Get Requests      Misses      Sleeps  Spin Gets   Sleep1   Sleep2   Sleep3

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

cache buffers chains

2,881,936,948 	 3,070,271      41,336  3,031,456        0        0        0

row cache objects

  941,375,571   1,215,395         852  1,214,606        0        0        0

object queue header operation

  763,607,977     949,376      30,484    919,782        0        0        0

cache buffers lru chain

  376,874,990     705,162       3,192    702,090        0        0        0

    這 裡top latch是cache buffers chains. Cache Buffers Chains latches是用來保護buffer caches中的buffers。在我們讀取資料時，這個latch是正常需要獲得的。Sleep的數字上升代表session在讀取buffers時開 始等待這個latch。爭用通常來自於不良的SQL要讀取相同的buffers。

    在我們這個例子裡，雖然讀取buffer的操作發生了 28億次，但是隻sleep了41,336次，可以認為是比較低的。Avg Slps/Miss（Sleeps/ Misses）也比較低。這表明當前Server有能力處理這樣多的資料，所以沒有發生Cache Buffers Chains latch的爭用。

值得注意的wait events

  • CPU time events

    CPU變為top wait event並不總是代表出現了問題。但是如果同時資料庫效能比較慢，那麼就需要進一步分析了。首先，檢查AWR報告的“ SQL ordered by CPU Time ”部分，看是否某個特定的SQL使用了大量的CPU。

    SQL ordered by CPU Time

-> Resources reported for PL/SQL code includes the resources used by all SQL

  statements called by the code.

-> % Total is the CPU Time divided into the Total CPU Time times 100

-> Total CPU Time (s):          56,207

-> Captured SQL account for      114.6% of Total



   CPU      Elapsed                  CPU per          % Total


 Time (s)   Time (s)  Executions     Exec (s) % Total DB Time SQL Id
---------- ---------- ------------ ----------- ------- ------- -------------

    20,349     24,884          168      121.12    36.2     9.1 7bbhgqykv3cm9
Module: DBMS_SCHEDULER
DECLARE job BINARY_INTEGER := :job; next_date TIMESTAMP WITH TIME ZONE := :myda
te; broken BOOLEAN := FALSE; job_name VARCHAR2(30) := :job_name; job_subname
VARCHAR2(30) := :job_subname; job_owner VARCHAR2(30) := :job_owner; job_start
TIMESTAMP WITH TIME ZONE := :job_start; job_scheduled_start TIMESTAMP WITH TIME


    Analysis:

    • -> Total CPU Time (s): 56,207
      它代表了15分鐘的CPU time。但是這個數字是否有問題取決於整個報告的時間。
    • Top SQL使用的CPU是 20,349秒（大概5分鐘）
    • 整個CPU時間佔DB Time的9.1%
    • 執行了168次，這個執行次數跟之前提到的幾個SQL是一樣的，說明這些SQL可能都是被同一個JOB呼叫的。

    其他潛在的CPU相關的問題：

    • 檢查是否有其他等待事件與高CPU 事件同時出現 如cursor: pin S問題可能引起高CPU使用：
       
    • 資料庫以外的CPU使用率過高 如果一個資料庫以外的程式使用了過多CPU，那麼資料庫程式能夠獲得的CPU就會減少，資料庫效能就會受到影響。在這種情況下，執行OSWather或者其他的OS工具去發現是哪個程式使用了過多CPU

       
    • 診斷CPU使用率 可以參考我已經寫的《》文章。

  • 'Log file sync' waits

    當 一個user session commit或rollback時，log writer程式會把redo從log buffer中寫入redo logfile檔案。AWR報告會幫助我們來確定是否存在這方面的問題，並且確認是否是由物理IO引起。

  • Buffer busy waits

    當 一個session從buffer cache讀取一個buffer時，如果這個buffer處於busy的狀態（由於其它session正在向其中讀取資料，或者是由於這個buffer被 其它的session以不相容模式持有），那麼這個session就會等待這個事件。

使用ADDM的報告

當分析效能問題時，除了AWR報告，我們還可以同時參照ADDM報告，對於潛在的效能問題，它同時提供了具體的解決方案建議。

ADDM報告相比AWR報告來說，它提供了可讀性更好的建議；當然應該同時參照ADDM報告和AWR報告來得到更準確地診斷。

Statspack

AWR報告取代了舊有的staspack及bstat/estat報告。

 



2014.09.03 09:30
share you knowledge with the world.

 

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/29734436/viewspace-1263815/，如需轉載，請註明出處，否則將追究法律責任。

相關文章