Oracle數據庫由dataguard備庫引發的log file sync等待

導讀：

最近數據庫常常出現會話阻塞的報警，過一會又會自動消失，昨天晚上剛好發生了一次，因而趕忙進行了查看，不看不知道，一看嚇一跳，發現是由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

（二）分析

查看報警期間的歷史會話信息：

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。

查詢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;

在本案例中，一共出現了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的等待步驟以下：

步驟①和②時所經歷的時間就是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)；
• 使用批量提交，減小提交的次數；

（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;

【完】