Oracle資料庫由dataguard備庫引起的log file sync等待

gegeman發表於2020-11-26
Oracle資料庫

導讀：

最近資料庫經常出現會話阻塞的報警，過一會又會自動消失，昨天晚上恰好發生了一次，於是趕緊進行了檢視，不看不知道，一看嚇一跳，發現是由dataguard引起的log file sync等待。我們知道，通常log file sync等待都是由頻繁寫日誌造成的，這次居然是由DG環境引起的。


（一）問題描述

資料庫：Oracle 11.2.0.4，單機版，有Dataguard環境

作業系統：centos 7.4


通過zabbix監控到的會話阻塞資訊如下圖，這裡是自定義的監控，解釋如下：

使用者usera,其session id為2663，session serial為27727，該會話未在執行SQL語句，但是卻一直處於非空閒等待，等待的事件為log file sync，一共等待了548s

clipboard


（二）分析

檢視報警期間的歷史會話資訊：

select  sample_time, session_id,session_serial#,session_type,user_id,sql_id,sql_plan_operation,event,
        blocking_session,blocking_session_serial#,PROGRAM,MACHINE    
from    v$active_session_history a
where   a.sample_time > to_date('2020-11-25 20:40:00','yyyy-mm-dd hh24:mi:ss')
and     a.sample_time < to_date('2020-11-25 20:59:00','yyyy-mm-dd hh24:mi:ss')
and     blocking_session is not null
order by a.sample_time;

可以看到，會話1333，2191，2663均被會話1331阻塞了，等待事件是log file sync，它們在等待的會話為1311。

snipaste_2020-11-26_11-38-30

查詢1331會話資訊，發現是日誌寫程式LGWR，1311會話不再被其它會話阻塞，可以判定該會話為阻塞源頭，1331會話的等待事件是LGWR-LNS wait on channel。

select  sample_time, session_id,session_serial#,session_type,user_id,sql_id,event,
        blocking_session_status,blocking_session,PROGRAM,MACHINE    
from    v$active_session_history a
where   a.sample_time > to_date('2020-11-25 20:40:00','yyyy-mm-dd hh24:mi:ss')
and     a.sample_time < to_date('2020-11-25 20:59:00','yyyy-mm-dd hh24:mi:ss')
and     a.session_id = 1331
order by a.sample_time;

snipaste_2020-11-26_11-42-47


在本案例中，一共出現了2種型別的非空閒等待事件：

  • log file sync
  • LGWR-LNS wait on channel（阻塞源頭）

什麼是log file sync：當使用者提交一個事務之後就開始等待log file sync，直到LGWR程式完成了對SCN的傳播和對應重做日誌的寫入操作。所以log file sync的等待時間是由重做日誌I/O時間和SCN傳播時間兩部分構成的，如果還使用了DataGuard，且日誌傳送時使用了同步+確認(SYNC+AFFRIM)選項時，那麼LGWR還需在使用者提交事務之後將重做日誌資訊傳遞到遠端備庫節點。總結一下，log file sync的計算公式如下：

使用者程式log file sync等待時間 = LGWR執行重做日誌I/O時間 + SCN傳播時間 + LGWR傳送重做日誌到備庫的時間。

在資料庫例項中，log file sync的等待步驟如下：

clipboard

步驟①和②時所經歷的時間就是log file sync所經歷的時間。a1~a4是LGWR傳送重做日誌到備庫的過程，b1~b4是LGWR傳播SCN的過程，c1~c2是LGWR將重做日誌寫入到重做日誌檔案的過程。

a1~a4代表LGWR傳送重做日誌到DataGuard備庫，過程如下：

a1：LGWR將事務對應的重做資訊傳送給本地節點的LNS(network server)程式

a2：LNS程式通過網路將重做資訊傳送給備庫的RFS(remote file server)程式

a3：RFS程式將重做日誌資訊寫入到備庫的備用重做日誌檔案(Standby redo log)，返回訊息給主庫的LNS程式

a4：主庫的LNS程式通知LGWR程式重做資訊已經寫入到備庫的備用重做日誌檔案


b1~b4代表LGWR傳播SCN，SCN是資料庫內部的時鐘，不重複，單項增長，SCN是針對資料庫的，不是針對例項的，也就是說，對於RAC資料庫，雖然有多個例項，這些例項會使用相同的SCN，但是每個例項都可以進行各自的任務，這就意味著例項之間需要傳播SCN。對於分散式資料庫（例如，使用了DB Link），也同樣存在著同步SCN的概念。同步SCN的過程如下：

b1：LGWR程式將事務提交的SCN傳送給本地的一個LMS程式

b2：本地節點的LMS程式將包含了SCN的訊息傳送給所有遠端節點的LMS程式

b3：所有遠端節點的LMS程式接受到了SCN訊息並反饋給本地節點的LMS程式

b4：本地節點的LMS程式通知LGWR，所有遠端節點都受到了事務的SCN


c1~c2代表LGWR執行重做日誌寫I/O。過程如下：

c1：LGWR程式將redo buffer cache中的日誌寫入到online redo log

c2：寫完之後LGWR會收到通知已完成


在分析完log file sync等待事件的過程之後，基本上可以知道其形成原因了。然而，新的問題又來了，log file sync等待由3部分原因構成，在我的環境中，到底是LGWR執行重做日誌比較慢，還是SCN傳播時間存在異常等待，還是LGWR傳送重做日誌到備庫存在效能瓶頸，這個時候我們就需要確認log file sync的並發現象了，我們繼續分析。


（1）由LGWR執行重做日誌I/O引起的log file sync

如果是由於LGWR將日誌寫入到online redo log引起的I/O問題，往往會伴隨著log file parallel write等待事件出現，也就是說，如果log file sync和log file parallel write一起出現，那麼往往是存放線上日誌檔案的磁碟I/O出問題了，有可能是磁碟吞吐量較差，也有可能是頻繁的小I/O操作，磁碟I/O問題的主要解決方案如下：

  • 優化了redo日誌的I/O效能，儘量使用快速磁碟，不要把redo log file存放在raid 5的磁碟上；
  • 加大日誌緩衝區(log buffer)；
  • 使用批量提交，減少提交的次數；

clipboard


（2）由SCN傳播引起的log file sync

由SCN傳播引起的log file sync等待事件幾乎沒有見過，個人覺得SCN傳播引起log file sync的概率較小，可以忽略

SQL> SELECT NAME FROM v$event_name a WHERE a.name LIKE '%SCN%' OR a.name LIKE '%LMS%';

NAME
----------------------------------------------------------------
retry contact SCN lock master
ges master to get established for SCN op


（3）由LGWR傳送重做日誌到備庫引起的log file sync

需要特別注意的是，只有在LOG_ARCHIVE_DEST_n引數中使用了"SYNC，AFFIRM"屬性時，log file sync等待事件才會與LGWR傳送日誌有關，如果使用了其它屬性，不用考慮。

LNS程式DataGuard環境中主庫用來傳送日誌到備庫的程式，檢視所有與之相關的等待事件。

SQL> SELECT NAME FROM v$event_name a WHERE a.name LIKE '%LNS%';

NAME
----------------------------------------------------------------
LNS wait on ATTACH
LNS wait on SENDREQ
LNS wait on DETACH
LNS wait on LGWR
LGWR wait on LNS
LNS ASYNC archive log
LNS ASYNC dest activation
LNS ASYNC end of log
LNS simulation latency wait
LGWR-LNS wait on channel

回過頭，再次檢視我們的生產環境的問題，是log file sync伴隨著LGWR-LNS wait on channel出現，再次確認資料庫的引數資訊，發現資料庫執行在最大可用模式，備庫採用了同步(sync)方式傳送資料。

SQL> select name,open_mode,database_role,protection_mode,protection_level from v$database;

NAME      OPEN_MODE            DATABASE_ROLE    PROTECTION_MODE      PROTECTION_LEVEL    
--------- -------------------- ---------------- -------------------- --------------------
ORCL2     READ WRITE           PRIMARY          MAXIMUM AVAILABILITY MAXIMUM AVAILABILITY


SQL> show parameter log
NAME                          TYPE    VALUE                                                                                                
----------------------------- ------- ---------------------------------------------------------------------------------------------------- 
log_archive_dest_2            string  SERVICE=adg_orcl LGWR SYNC VALID_FOR=(ONLINE_LOGFILES,PRIMARY_ROLE)                                
                                      DB_UNIQUE_NAME=adg_orcl

再進一步分析"LGWR-LNS wait on channel"等待事件：

什麼是LGWR-LNS wait on channel：這個等待事件監視LGWR或LNS程式等待在KSR通道上接收訊息所花費的時間（This wait event monitors the amount of time spent by the log writer (LGWR) process or the network server processes waiting to receive messages on KSR channels.         Data Guard Wait Events (Doc ID 233491.1) ）。

KSR通道的解釋:https://docs.oracle.com/en/database/oracle/oracle-database/12.2/refrn/DBA_HIST_CHANNEL_WAITS.html#GUID-682C58F4-5787-4C8E-844C-9DFE04612BDD。


可以斷定，資料庫的異常等待是由於主庫的LNS程式同步傳送線上日誌資訊給DG環境引起的，且引起的瓶頸在備庫端。想到我們的主庫是高配的物理伺服器，備庫是低配的雲主機(虛擬機器)，出現這種問題也就不足為奇了。


（三）解決方案

使用非同步方式傳送日誌資訊，修改日誌傳送方式為非同步(async)傳送

SQL> alter system set log_archive_dest_2= SERVICE="adg_orcl" LGWR ASYNC VALID_FOR=(all_logfiles, primary_role) DB_UNIQUE_NAME="adg_orcl" scope=both;

-- 重新啟用通道
SQL> alter system set log_archive_dest_state_2= defer;
SQL> alter system set log_archive_dest_state_2= enable;



【完】

相關文章