平臺(tái):sunos 5.8 generic_108528-23 sun4u sparc sunw,ultra-enterprise
數(shù)據(jù)庫(kù):8.1.5.0.0
癥狀:響應(yīng)緩慢，應(yīng)用請(qǐng)求已經(jīng)無(wú)法返回
登陸數(shù)據(jù)庫(kù),發(fā)現(xiàn)redo日志組除current外都處于active狀態(tài)
oracle:/oracle/oracle8>sqlplus "/ as sysdba"

sql*plus: release 8.1.5.0.0 - production on thu jun 23 18:56:06 2005

(c) copyright 1999 oracle corporation.  all rights reserved.

connected to:
oracle8i enterprise edition release 8.1.5.0.0 - production
with the partitioning and java options
pl/sql release 8.1.5.0.0 - production
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

9 rows selected.

sql> /

    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

9 rows selected.

如果日志都處于active狀態(tài)，那么顯然dbwr的寫(xiě)已經(jīng)無(wú)法跟上log switch觸發(fā)的檢查點(diǎn)。

接下來(lái)讓我們檢查一下dbwr的繁忙程度:
sql> !
oracle:/oracle/oracle8>ps -ef|grep ora_
  oracle  2273     1  0   mar 31 ?       57:40 ora_smon_hysms02
  oracle  2266     1  0   mar 31 ?       811:42 ora_dbw0_hysms02
  oracle  2264     1 16   mar 31 ?       16999:57 ora_pmon_hysms02
  oracle  2268     1  0   mar 31 ?       1649:07 ora_lgwr_hysms02
  oracle  2279     1  0   mar 31 ?        8:09 ora_snp1_hysms02
  oracle  2281     1  0   mar 31 ?        4:22 ora_snp2_hysms02
  oracle  2285     1  0   mar 31 ?        9:40 ora_snp4_hysms02
  oracle  2271     1  0   mar 31 ?       15:57 ora_ckpt_hysms02
  oracle  2283     1  0   mar 31 ?        5:37 ora_snp3_hysms02
  oracle  2277     1  0   mar 31 ?        5:58 ora_snp0_hysms02
  oracle  2289     1  0   mar 31 ?        0:00 ora_d000_hysms02
  oracle  2287     1  0   mar 31 ?        0:00 ora_s000_hysms02
  oracle  2275     1  0   mar 31 ?        0:04 ora_reco_hysms02
  oracle 21023 21012  0 18:52:59 pts/65   0:00 grep ora_

dbwr的進(jìn)程號(hào)是2266。
使用top命令觀察一下:
oracle:/oracle/oracle8>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
  6957 smspf     15  29   10   63m   14m sleep  107.7h  0.76% java
 17393 smspf      1  30    0 1356m 1322m cpu/1  833:05  0.58% oracle
 29299 smspf      5  58    0 8688k 5088k sleep   18.5h  0.38% fee_ftp_get
 21043 oracle     1  43    0 3264k 2056k cpu/9    0:01  0.31% top
 20919 smspf     17  29   10   63m   17m sleep  247:02  0.29% java
 25124 smspf      1  58    0   16m 4688k sleep    0:35  0.25% smif_status_rec
  8086 smspf      5  23    0   21m   13m sleep   41.1h  0.24% fee_file_in
 16009 root       1  35    0 4920k 3160k sleep    0:03  0.21% sshd2
 25126 smspf      1  58    0 1355m 1321m sleep    0:26  0.20% oracle
  2266 oracle     1  60    0 1357m 1317m sleep  811:42  0.18% oracle
 11628 smspf      7  59    0 3440k 2088k sleep    0:39  0.16% sgip_client_ltz
 26257 smspf     82  59    0  447m  178m sleep  533:04  0.15% java

我們注意到，2266號(hào)進(jìn)程消耗的cpu不過(guò)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
    1.8   38.4   32.4  281.0  0.0  0.7    0.0   16.4   0  29 c0t10d0
    1.8   38.4   32.4  281.0  0.0  0.5    0.0   13.5   0  27 c0t11d0
   24.8   61.3 1432.4  880.1  0.0  0.5    0.0    5.4   0  26 c1t1d0
    0.0    0.0    0.0    0.0  0.0  0.0    0.0    9.1   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    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 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.0    8.0    0.0   42.7  0.0  0.1    0.0    9.3   0   7 c0t10d0
    0.0    8.0    0.0   42.7  0.0  0.1    0.0    9.1   0   7 c0t11d0
   11.0   65.7  978.7  525.3  0.0  1.4    0.0   17.7   0  99 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   87.7    2.7  433.7  0.0  2.2    0.0   24.9   0  90 c0t10d0
    0.0   88.3    0.0  436.5  0.0  1.8    0.0   19.9   0  81 c0t11d0
   89.0   54.0  725.4  432.0  0.0  2.1    0.0   14.8   0 100 c1t1d0
    0.0    0.0    0.0    0.0  0.0  0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)

我們注意到，存放數(shù)據(jù)庫(kù)的主要卷c1t1d0的繁忙程度始終處于99~100,而寫(xiě)速度卻只有500k/s左右，這個(gè)速度是極為緩慢的。
(%b percent of time the disk is busy (transactions in progress)
kw/s kilobytes written per second)
根據(jù)我們的常識(shí)t3盤(pán)陣通常按char寫(xiě)速度可以達(dá)到10m/s左右，以前測(cè)試過(guò)一些tpcc指標(biāo)，可以參考:use bonnie to test system io speed。
而正常情況下的數(shù)據(jù)庫(kù)隨機(jī)寫(xiě)通常都在1~2m左右，顯然此時(shí)的磁盤(pán)已經(jīng)處于不正常狀態(tài)，經(jīng)過(guò)確認(rèn)的確是硬盤(pán)發(fā)生了損壞，raid5的group中損壞了一塊硬盤(pán)。
經(jīng)過(guò)更換以后系統(tǒng)逐漸恢復(fù)正常。

posted by eygle at june 26, 2005