2015年4月27日，晚上6點左右，電渠3g2庫ORACLE RAC系統節點1出現大量的direct path write等待事件，導致大量的會話堆積，節點1幾乎無法使用，應用受到影響，相關處理流程如下：
環境：
作業系統：hp-unix
資料庫版本：10.2.0.5
故障描述：開始是27號上午9左右，應用開發有人執行update語句，發現執行好長時間沒有完成，然後在資料庫中查詢並試圖殺死會話，但是執行殺會話後再作業系統中依然有相關會話存在，
然後，試圖使用kill -9殺程式，發現相關程式依然無法殺死；接下來，到晚上6點是相關會話大量積壓的過程，資料庫伺服器實在無法承受會話繼續積壓（24800個），晚上7點左右與業務方溝通後
決定重啟資料庫，發現資料庫無法正常的shutdown immediate，又嘗試shutdown abort，但是startup的時候例項無法啟動，查明是update的相關程式很多都積壓在後臺，決定重啟主機伺服器，節點1重啟後正常，節點2又出現節點1類似的徵兆，為了處理故障，避免累次重啟無法解決故障，先保護現場待故障處理完成。
接下來的故障定位如下：
從dba_hist_active_sess_history檢視查詢資料庫取樣變化發現上午10點左右開始出現會話堆積：

select sample_time,count(*) from dba_hist_active_sess_history where dbid=3965601902 and
snap_id>49716 and snap_id<49720 and sample_time and sample_time>to_date('20150527 10:18:00','yyyymmdd hh24:mi:ss') group by sample_time
order by sample_time;

SAMPLE_TIME COUNT(*)
---------------------------------------- ----------
27-MAY-15 10.18.04.924 AM 4
27-MAY-15 10.18.12.694 AM 3
27-MAY-15 10.18.15.024 AM 3
27-MAY-15 10.18.22.794 AM 1
27-MAY-15 10.18.25.124 AM 4
27-MAY-15 10.18.35.224 AM 3
27-MAY-15 10.18.45.324 AM 1
27-MAY-15 10.18.55.434 AM 2
27-MAY-15 10.19.03.204 AM 1
27-MAY-15 10.19.13.304 AM 1
27-MAY-15 10.19.23.404 AM 2
27-MAY-15 10.19.35.834 AM 2
27-MAY-15 10.19.43.614 AM 1
27-MAY-15 10.19.45.934 AM 1
27-MAY-15 10.19.53.714 AM 2
27-MAY-15 10.19.56.044 AM 2
27-MAY-15 10.20.03.814 AM 1
27-MAY-15 10.20.06.144 AM 1
27-MAY-15 10.20.13.914 AM 1
27-MAY-15 10.20.16.244 AM 1
27-MAY-15 10.20.24.014 AM 3
27-MAY-15 10.20.26.343 AM 2
27-MAY-15 10.20.34.114 AM 1
27-MAY-15 10.20.36.443 AM 3
27-MAY-15 10.20.44.224 AM 1
27-MAY-15 10.20.46.553 AM 1
27-MAY-15 10.20.54.324 AM 9
27-MAY-15 10.21.04.424 AM 13
27-MAY-15 10.21.06.753 AM 7
27-MAY-15 10.21.14.525 AM 21
27-MAY-15 10.21.16.853 AM 17
27-MAY-15 10.21.24.624 AM 32
27-MAY-15 10.21.26.953 AM 1
27-MAY-15 10.21.34.814 AM 50
27-MAY-15 10.21.37.053 AM 2
27-MAY-15 10.21.44.914 AM 49
27-MAY-15 10.21.47.163 AM 2
27-MAY-15 10.21.55.014 AM 61
27-MAY-15 10.21.57.263 AM 2
27-MAY-15 10.22.05.116 AM 69
27-MAY-15 10.22.07.363 AM 12
27-MAY-15 10.22.15.216 AM 77
27-MAY-15 10.22.17.463 AM 12
27-MAY-15 10.22.25.316 AM 87
27-MAY-15 10.22.27.562 AM 13
27-MAY-15 10.22.35.426 AM 112
27-MAY-15 10.22.37.662 AM 47
27-MAY-15 10.22.45.526 AM 121
27-MAY-15 10.22.47.772 AM 7
27-MAY-15 10.22.55.626 AM 129
27-MAY-15 10.22.57.872 AM 10

從上表可以發現，正常情況下4s對會話等待事件取樣的記錄從10點30左右開始增加，從會話取樣歷史檢視檢視相關等待事件如下：

select sample_time,event,count(*) from dba_hist_active_sess_history where dbid=3965601902 and
snap_id>49716 and snap_id<49720 and sample_time and sample_time>to_date('20150527 10:20:00','yyyymmdd hh24:mi:ss') group by sample_time,event
order by sample_time;

SAMPLE_TIME EVENT COUNT(*)
---------------------------------------- ---------------------------------------- ----------
27-MAY-15 10.20.03.814 AM 1
27-MAY-15 10.20.06.144 AM db file sequential read 1
27-MAY-15 10.20.13.914 AM 1
27-MAY-15 10.20.16.244 AM 1
27-MAY-15 10.20.24.014 AM db file sequential read 1
27-MAY-15 10.20.24.014 AM 2
27-MAY-15 10.20.26.343 AM 2
27-MAY-15 10.20.34.114 AM db file sequential read 1
27-MAY-15 10.20.36.443 AM 3
27-MAY-15 10.20.44.224 AM 1
27-MAY-15 10.20.46.553 AM 1
27-MAY-15 10.20.54.324 AM db file sequential read 1
27-MAY-15 10.20.54.324 AM direct path write 8
27-MAY-15 10.21.04.424 AM db file sequential read 1
27-MAY-15 10.21.04.424 AM direct path write 10
27-MAY-15 10.21.04.424 AM enq: TX - row lock contention 1
27-MAY-15 10.21.04.424 AM 1
27-MAY-15 10.21.06.753 AM db file sequential read 1
27-MAY-15 10.21.06.753 AM 6
27-MAY-15 10.21.14.525 AM db file sequential read 1
27-MAY-15 10.21.14.525 AM direct path write 17
27-MAY-15 10.21.14.525 AM enq: TX - row lock contention 2
27-MAY-15 10.21.14.525 AM 1
27-MAY-15 10.21.16.853 AM gc current block 2-way 1
27-MAY-15 10.21.16.853 AM gc current grant 2-way 1
27-MAY-15 10.21.16.853 AM kjbdrmcvtq lmon drm quiesce: ping completion 1
27-MAY-15 10.21.16.853 AM log file sync 8
27-MAY-15 10.21.16.853 AM wait for scn ack 1
27-MAY-15 10.21.16.853 AM 5
27-MAY-15 10.21.24.624 AM db file sequential read 1
27-MAY-15 10.21.24.624 AM direct path write 26
27-MAY-15 10.21.24.624 AM enq: TX - row lock contention 3
27-MAY-15 10.21.24.624 AM gcs drm freeze in enter server mode 1
27-MAY-15 10.21.24.624 AM 1
27-MAY-15 10.21.26.953 AM 1
27-MAY-15 10.21.34.814 AM db file sequential read 1
27-MAY-15 10.21.34.814 AM direct path write 33
27-MAY-15 10.21.34.814 AM enq: TX - row lock contention 4
27-MAY-15 10.21.34.814 AM gcs drm freeze in enter server mode 1
27-MAY-15 10.21.34.814 AM row cache lock 10
27-MAY-15 10.21.34.814 AM 1
27-MAY-15 10.21.37.053 AM db file sequential read 1
27-MAY-15 10.21.37.053 AM 1
27-MAY-15 10.21.44.914 AM db file sequential read 1
27-MAY-15 10.21.44.914 AM direct path write 42
27-MAY-15 10.21.44.914 AM enq: TX - row lock contention 4
27-MAY-15 10.21.44.914 AM enq: US - contention 1
27-MAY-15 10.21.44.914 AM gcs drm freeze in enter server mode 1
27-MAY-15 10.21.47.163 AM log file parallel write 1
27-MAY-15 10.21.47.163 AM 1
27-MAY-15 10.21.55.014 AM db file sequential read 1
27-MAY-15 10.21.55.014 AM direct path write 42
27-MAY-15 10.21.55.014 AM enq: TX - row lock contention 5
27-MAY-15 10.21.55.014 AM gc current block 2-way 1
27-MAY-15 10.21.55.014 AM gc current grant 2-way 2
27-MAY-15 10.21.55.014 AM kjbdrmcvtq lmon drm quiesce: ping completion 1
27-MAY-15 10.21.55.014 AM log file sync 3
27-MAY-15 10.21.55.014 AM wait for scn ack 1
27-MAY-15 10.21.55.014 AM 5
27-MAY-15 10.21.57.263 AM db file parallel write 1
27-MAY-15 10.21.57.263 AM 1

如上表所示，從上午10:20開始出現等待事件direct path write，緊接著出現 enq: TX - row lock contention等待事件，direct path write持續增加導致大量會話積壓。
接下來查詢等待事件direct path write等待的例項、資源的id號、等待次數的積壓情況：

select instance_number,p1,count(*) from dba_hist_active_sess_history where dbid=3965601902 and
snap_id>49716 and snap_id<49730 and sample_time and event='direct path write'
and sample_time>to_date('20150527 10:20:00','yyyymmdd hh24:mi:ss')
group by instance_number,p1 order by 3 ;

INSTANCE_NUMBER P1 COUNT(*)
--------------- ---------- ----------
1 461 1
1 494 1
1 372 1
1 495 1
2 581 1
2 285 1
1 479 1
2 495 1
2 317 1
1 587 1
1 543 1
2 316 1
2 438 1
2 498 1
2 497 1
2 499 2
1 520 2
2 437 2
1 466 2
2 496 2
1 556 2
1 439 2
1 438 2
1 316 2
1 498 2
2 439 3
1 474 3
1 436 3
1 519 3
1 496 4
1 475 4
1 497 4
2 475 4
2 494 4
2 436 4
1 499 5
1 437 6
2 474 7
1 589 59128
2 588 84346

從上表可以開出，rac兩個節點均有由於direct path write等待的資源並且有大量的等待，接下來查詢物件589、588對應的物理裝置：

SQL> select file_name,tablespace_name from dba_data_files where file_id=&file;
Enter value for file: 588
old 1: select file_name,tablespace_name from dba_data_files where file_id=&file
new 1: select file_name,tablespace_name from dba_data_files where file_id=588

FILE_NAME TABLESPACE_NAME
--------------------------------- ------------------------------
/dev/essdb2vg5/rdb2vg5_10_lv001 TBS_TRADE_D10
SQL> /
Enter value for file: 589
old 1: select file_name,tablespace_name from dba_data_files where file_id=&file
new 1: select file_name,tablespace_name from dba_data_files where file_id=589
FILE_NAME TABLESPACE_NAME
--------------------------------- ------------------------------
/dev/essdb2vg5/rdb2vg5_10_lv002 TBS_TRADE_D09

經系統維護責任人確認，這兩個裸裝置是昨天晚上新擴容的4塊盤，先兩塊盤做raid0，再兩個raid0組raid1，然後劃分的每10G大小共40個的裸裝置，然後對資料庫表空間擴的容；透過現場硬體同事的反應，換上去的4塊盤，有兩塊盤是舊盤，又經儲存工程師確認新加的raid1組被鎖住了。由此可知，由於儲存RAID被鎖，相關的磁碟無法寫入，資料庫才會出現direct path write等待事件導致大量會話積壓。
後續處理：由於這是電商平臺，業務對資料很敏感，考慮先進行備份，查明有問題的兩個裸裝置分別屬於兩個不同的表空間，2個表空間是2個不同方案下相同名稱的分割槽表的photo欄位分割槽。先檢驗是否能讀，方法如下，結果是讀失敗，所以排除掉備份（無論是exp、expdp、rman）；由於業務方要求28號上午9點必須恢復業務，經過多次嘗試，時間已是27號晚上10點多，進行資料庫rman全備恢復消耗時間不可控，考慮基於歸檔的恢復。
select /*+ parallel(t 8)*/* from "UCR_TRADE_03"."TF_F_IDCARD" partition(PAR_TF_B_IDCARD_VERIFY_8) t;
基於歸檔的恢復操作流程，通知儲存工程師，準備2個與故障裸裝置相同容積的裸裝置，指定好資料庫使用者許可權，在資料庫中將2個有問題的裸裝置進行下線，然後重定向到新的裸裝置，再將節點2上從今天早上開始對資料庫擴容的時間6:00時的歸檔複製到節點1上，進行recover。
新的裸裝置如下：
/dev/essdb2vg7/rdb2vg7_10_lv001
/dev/essdb2vg7/rdb2vg7_10_lv002
表空間下線後重定向：
SQL> alter database create datafile 588 as '/dev/essdb2vg7/rdb2vg7_10_lv001';
SQL> alter database create datafile 589 as '/dev/essdb2vg7/rdb2vg7_10_lv002';
基於歸檔恢復：
SQL> recover datafile '/dev/essdb2vg7/rdb2vg7_10_lv001';
SQL> recover datafile '/dev/essdb2vg7/rdb2vg7_10_lv002';
恢復完畢後將資料檔案上線：
SQL> alter database datafile '/dev/essdb2vg7/rdb2vg7_10_lv001' online;
SQL> alter database datafile '/dev/essdb2vg7/rdb2vg7_10_lv002' online;
如果有必要，回退到故障點：
停止資料庫
shutdown immediate；
startup mount；

alter database rename file '/dev/essdb2vg5/rdb2vg5_10_lv038' to '/dev/essdb2vg5/rdb2vg5_10_lv001';
alter database rename file '/dev/essdb2vg5/rdb2vg5_10_lv039' to '/dev/essdb2vg5/rdb2vg5_10_lv002';

alter database open；
幸運的是，基於歸檔的資料檔案恢復是成功的。

ORACLE等待事件：direct path write

相關文章