AWR 報告深度解讀：Redo Nowait指標的演算法和診斷

導讀：本文將對Redo Nowait指標的演算法和診斷進行深度解析。

AWR知識體系：

曾經遇到過一個效能故障，資料庫的檢查點執行的非常緩慢，直接導致所有日誌組都處於活動狀態，資料庫處於不斷停頓的『打嗝』工作狀態。

檢查V$LOG檢視，可以獲得日誌狀態，除了CURRENT日誌組，其他日誌都處於ACTIVE狀態，而且後面的幾組日誌都是DBA最新新增的：

SQL> select * from v$log;
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
         1          1     520403   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         2          1     520404   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         3          1     520405   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         4          1     520406   31457280          1 NO  CURRENT             1.3861E+10 23-JUN-05
         5          1     520398   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         6          1     520399   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         7          1     520400  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         8          1     520401  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         9          1     520402  104857600          1 NO  ACTIVE              1.3861E+10 23-JUN-05

如果日誌都處於Active狀態，那麼顯然是DBWR的寫出已經無法跟上Log Switch切換觸發的檢查點。

接下來讓我們檢查一下DBWR的繁忙程度:

oracle:/oracle >ps -ef|grep ora_dbw
  oracle  2266     1  0   Mar 31 ?       811:42 ora_dbw0_hysms02
  oracle 21023 21012  0 18:52:59 pts/65   0:00 grep ora_dbw

這裡可以看到DBWR的程式號是2266，接下來使用Top命令觀察一下其CPU資源使用情況:

oracle:/oracle >top
last pid: 21145;  load averages:  3.38,  3.45,  3.67               18:53:38
725 processes: 711 sleeping, 1 running, 10 zombie, 3 on cpu
CPU states: 35.2% idle, 40.1% user,  9.4% kernel, 15.4% iowait,  0.0% swap
Memory: 3072M real, 286M free, 3120M swap in use, 1146M swap free
 
   PID USERNAME THR PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
 11855 smspf      1  59    0 1355M 1321M cpu/0   19:32 16.52% oracle
  2264 oracle     1   0    0 1358M 1316M run    283.3H 16.36% oracle
 11280 oracle     1  13    0 1356M 1321M sleep   79.8H  0.77% oracle
21043 oracle     1  43    0 3264K 2056K cpu/9    0:01  0.31% top
2266 oracle  1  60  0 1357M 1317M sleep  811:42  0.18% oracle
 26257 smspf     82  59    0  447M  178M sleep  533:04  0.15% java

注意到2266號程式消耗的CPU不過0.18%,顯然並不繁忙,那麼瓶頸就很可能在IO上。

使用IOSTAT工具檢查IO狀況。

gqgai:/home/gqgai>iostat -xn 3
                    extended device statistics             
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
........
    0.0    0.0    0.0    0.0  0.0  0.0    0.0    0.0   0   0 c0t6d0
    0.3    8.3    0.3   47.0  0.0  0.1    0.0    9.2   0   8 c0t10d0
    0.0    8.3    0.0   47.0  0.0  0.1    0.0    8.0   0   7 c0t11d0
   11.7   65.3  197.2  522.2  0.0  1.6    0.0   20.5   0 100 c1t1d0
    0.0    0.0    0.0    0.0  0.0  0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)
                    extended device statistics             
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
........
    0.0    0.0    0.0    0.0  0.0  0.0    0.0    0.0   0   0 c0t6d0
    0.3   13.7    2.7   68.2  0.0  0.2    0.0   10.9   0  12 c0t10d0
    0.0   13.7    0.0   68.2  0.0  0.1    0.0    9.6   0  11 c0t11d0
   11.3   65.3   90.7  522.7  0.0  1.5    0.0   19.5   0  99 c1t1d0
0.0    0.0    0.0    0.0  0.0  0.0    0.0    0.0   0   0

以上監控顯示存放資料庫的主要卷c1t1d0的繁忙程度始終處於99~100,而寫速度卻只有500K/s左右，這個速度是極為緩慢的。進一步的檢查確認是硬碟發生了損壞，Raid5的磁碟組中損壞了一塊硬碟，導致了磁碟I/O效能下降，經過更換以後系統逐漸恢復正常。

以下是另外一則類似的問題。最初有朋友提出的問題是，例項效率裡面的Redo Nowait指標代表的是什麼，為什麼會出現負數：

 

從資料庫的計算公式中可以找到這些比例的計算方法，雖然很多情況下，這些比例的參考意義不大：

--
--  Instance Efficiency Percentages
 
column ldscr  format a50
column nl format a60 newline;
select 'Instance Efficiency Percentages (Target 100%)' ldscr
      ,'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' ldscr
      ,'            Buffer Nowait %:'                  dscr
      , round(100*(1-:bfwt/:gets),2)                   pctval
      ,'      Redo NoWait %:'    
      , decode(:rent,0,to_number(null), round(100*(1-:rlsr/:rent),2))  pctval
      ,'            Buffer  Hit   %:'                  dscr
      , round(100*(1-(:phyr-:phyrd-:phyrdl)/:gets),2) pctval
      ,'   In-memory Sort %:'    
      , decode((:srtm+:srtd),0,to_number(null),
                               round(100*:srtm/(:srtd+:srtm),2))       pctval
      ,'            Library Hit   %:'                  dscr
      , round(100*:lhtr,2)                             pctval
      ,'       Soft Parse %:'    
      , round(100*(1-:hprs/:prse),2)                   pctval
      ,'         Execute to Parse %:'                  dscr
      , round(100*(1-:prse/:exe),2)                    pctval
      ,'        Latch Hit %:'    
      , round(100*(1-:lhr),2)                          pctval
      ,'Parse CPU to Parse Elapsd %:'                  dscr
      , decode(:prsela, 0, to_number(null)
                      , round(100*:prscpu/:prsela,2))  pctval
      ,'    % Non-Parse CPU:'
      , decode(:tcpu, 0, to_number(null)
                    , round(100*1-(:prscpu/:tcpu),2))  pctval
  from sys.dual;

從以上計算公式中可以找到：

Redo Nowait % = decode(:rent,0,to_number(null), round(100*(1-:rlsr/:rent),2))
 =  (1 – rlsr/rent) 100%

這裡的 rlsr = Redo Log space requests ，rent = Redo Entries 。從AWR報告中可以找到這兩個統計值，計算一下這個比率,和報告中的計算值完全吻合：

 Redo Nowait % = (1 – 133,566/44,038)*100% = -203.30 %

可是這個比率說明什麼？

重做日誌空間請求表明活動日誌檔案已滿，Oracle正在等待為重做日誌條目分配磁碟空間。這個比值越高說明在寫出Redo條目時等待越多，當比率為負數，說明已經處於嚴重的寫出等待之中。

那麼到底是什麼原因導致寫出不暢呢？是因為Redo量太大，還是因為磁碟效率過低呢？透過資料庫的其他統計資料可以進行進一步的分析。

這是一個 11.2.0.4的RAC叢集環境，從資料庫的概要資訊來看，平均每秒僅僅有 7K左右的Redo日誌，資料庫的物理寫也非常低，但是資料庫的每秒DB Time卻高達259.7 。

 

進一步的，從 Top Events資料資訊中可以看出，整體的 I/O 非常緩慢，User/IO的平均等待時間高達 410毫秒，db file sequential read的平均等待時間也高達 1779毫秒，這說明I/O上出現了明顯的瓶頸。

 

在整個資料庫寫出量並不大的情況下，整體I/O延時卻非常高，在日誌組同樣處於高ACTIVE的情況下，出現大量的Log file Switch(checkpoint incomplete)等待。配合I/O層面的檢查發現這個案例同樣是儲存損壞硬碟導致的I/O能力下降。

資料庫的效能，是一個綜合因素，在遇到異常分析時，也需要綜合多方面的因素，才能夠快速而準確的定位根因，解決問題。

想了解更多關於資料庫、雲技術的內容嗎？

快來關注“資料和雲"、"雲和恩墨，"公眾號及"雲和恩墨"官方網站，我們期待大家一同學習與進步！

資料和雲小程式”DBASK“線上問答，隨時解惑，歡迎瞭解和關注！