天天看點

log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時

項目背景

基于TB級生産庫搭建一套OGG備庫,每天的日志量在200G左右,最近發現經常出現同步延遲幾十個小時,搞得有點煩,特此記錄一下處理過程。

系統環境

oracle 11.2.0.4+ogg12.2.0.1.0

延遲現象

GGSCI (cluster-10-176-50-29 as [email protected]) 169> info all

Program     Status      Group       Lag at Chkpt  Time Since Chkpt

MANAGER     RUNNING                                           
REPLICAT    RUNNING     REP_PS1     38:27:09      00:00:57    
REPLICAT    RUNNING     REP_PS2     00:00:02      00:00:10    
REPLICAT    RUNNING     REP_PS3     00:00:03      00:00:10    
REPLICAT    RUNNING     REP_PS4     00:00:03      00:00:03    
REPLICAT    RUNNING     REP_PS5     00:00:05      00:00:01    
REPLICAT    RUNNING     REP_PS6     00:00:05      00:00:01    
           

通過send rep_ps1,status檢視事務送出的記錄非常慢

問題分析與定位

1、在作業系統層面找到rep_ps1複制程序對應的作業系統PID

2、根據程序ID找到相應的會話

select a.spid process_id,b.SID,b.SERIAL#,b.PROGRAM,b.SQL_ADDRESS from v$process a,v$session b where a.ADDR=b.PADDR and a.SPID='77295'
           

3、檢視該會話所執行的SQL_ID和等待事件

select  m.SQL_ID,m.EVENT,m.BLOCKING_SESSION_STATUS,m.CURRENT_OBJ#,count(*)  from v$active_session_history m where m.SESSION_ID='1351'
group by m.SQL_ID,m.EVENT,m.BLOCKING_SESSION_STATUS,m.CURRENT_OBJ# 
order by 5,4
           

說明:這裡出現了大量的log file switch(checkpoint incomplete)等待事件

到這裡發現可能是redo日志組過少或日志組過小導緻的,查詢v l o g , v log,v log,vlogfile發現單個日志大小為1G,一共6組,但除了目前日志組狀态為current,其他日志組都為active,經過分析有以下原因:1、日志組不足;2、DBWN寫髒資料過慢

手動添加了4個日志組,每組大小為1G

alter database add logfile group 7 (‘redo7a.log’,‘redo7b.log’) size 1g;

alter database add logfile group 8 (‘redo8a.log’,‘redo8b.log’) size 1g;

alter database add logfile group 9 (‘redo9a.log’,‘redo9b.log’) size 1g;

alter database add logfile group 10 (‘redo10a.log’,‘redo10b.log’) size 1g;

觀察了幾分鐘發現同步速度依然沒有明顯提升,那就是DBWN程序寫入髒資料過慢,接着檢視AWR報告。

4、生成AWR報告,截圖如下。

log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時

system i/o事件産生的等待時間最長

log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時
log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時

這是可以看到背景程序db file async i/0 submit排在第一位

log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時

按I/O等待時間檢視看最耗I/O的SQL語句

到這裡基本能确認是I/O送出問題,導緻資料同步延遲的。

解決方法

1、搜尋相應的等件事件

檢視mos文檔 ID 1274737.1 部分如下:

The tests show the following behavior:

disk_asynch_io filesystemio_options strace DBWR AIO DBWR waits

FALSE NONE pwrite64 NO db file parallel write

FALSE ASYNCH pwrite64 NO db file parallel write

TRUE ASYNCH io_submit/ YES db file parallel write

io_getevents

TRUE NONE pwrite64 NO db file async I/O submit

說明:disk_asynch_io為TRUE,filesystemio_options為NONE的情況下 出現db file async I/O submit等待,可以設定filesystemio_options參數為ASYNCH或者SETALL,使得db file parallel write等待代替db file async I/O submit等待。

SQL> alter system set filesystemio_options=‘setall’ both=spfile

上述操作需要重新開機資料庫執行個體,重新開機後檢視參數是否生效

SQL> show parameter filesystem;

NAME TYPE VALUE

filesystemio_options string setall

disk_asynch_io boolean TRUE

select f.NAME,i.filetype_name,i.ASYNCH_IO,i.ACCESS_METHOD from v$datafile f ,v$iostat_file i 
where f.FILE#=i.FILE_NO
           
log file switch(checkpoint incomplete)導緻OGG同步延遲38個小時

調整完成後,通過send rep_ps1,status查詢同步的速度,有明顯的提升,先下班了,但事情還沒有完(還有SQL沒有優化)第二天上班發現同步延遲隻有10個小時,很明顯同步速度追上來了,接着優化SQL語句。

SQL語句優化就比較簡單了,從AWR報告找到最耗I/O的SQL語句進行優化,大部分都是對單表進行DELETE操作,而單表無索引導緻走全表掃描引起的同步效率低,對相應的表加上索引後,上午整個同步完全追上來了,到此整個同步延遲問題已圓滿解決。

總結

1、log file switch(checkpoint incomplete)不一定是完全是redo日志組過少或過小導緻的。

2、需要了解oracle的内部原理,LGWR進行在切換日志組時,如果下一組日志組的狀态為ACTIVE,會觸發checkpoint操作,進一步會讓DBWN将db buffer裡的髒資料刷回磁盤,對于磁盤的操作可以是同步寫操作也可以是異步寫操作,目前異步寫操作效率更高,需要看看oracle是否開啟的異步送出。

3、業務有設計不規劃的地方,如處理的表業務表中,好多都沒有主鍵,導緻删除操作都走全表掃描,同步效率低,出現延遲也就說得通了。