系統環境
兩節點的rac：aix6.1+oracle 11.2.0.3.3
awr裡展示出來的各種症狀（資料來自執行個體2）
雖然應用沒有報障，但awr報告裡的各種迹象已經很明顯了
(1) gc buffer busy acquire排進了top 5 timed foreground events
圖-1
(2) 除去db cpu在gc buffer busy acquire之後的就是gc cr block busy了
圖-2
(3) 2h21bq1mnc5kd這條sql的耗時裡85%的時間都在等待叢集有關的事件，且領先第二條太多了
圖-3
2h21bq1mnc5kd對應的完整sql是：select t.* from sd.sys_parameter t where t.param_class in (:1 , :2 )，且從語句的執行頻次來看1小時内(awr的采樣間隔是1小時)執行了260790次，約合72次/秒，并發度還是非常高的。
(4) % of capture=89.46表示在系統裡每發生100次的gc buffer busy等待就有89次來自于對象sd.sys_parameter，該值同樣遙遙領先第二條
圖-4
(5) cr blocks received的比例達到了43%，為實作一緻性讀，sd.sys_parameter表上存在大量的跨節點傳輸
圖-5
(6) 最後看下從v$active_session_history擷取的2h21bq1mnc5kd這條sql的gc事件，每秒鐘都有等待産生，争用的焦點在93号資料檔案的65696号block上
圖-5-1
雖然應用沒有變慢，但上述種種迹象已經引起了我的關注，做運維不就是要防患于未然麼。根據awr采樣到的結果，初步結論如下：
gc buffer busy acquire、gc cr block busy這兩個gc wait event與select t.* from sd.sys_parameter t where t.param_class in (:1 , :2 )這條sql有較大關系，該條sql執行時存在大量的跨節點讀，以實作一緻性讀。
（注：上述awr資料都來自執行個體2，執行個體1的awr報告未現任何異常情況）
了解gc buffer busy acquire和gc cr block busy
以最簡單的雙節點rac為例，當執行個體1發起一條select查詢某個block的時候，如果這個block不在本地的buffer cache，但是能在執行個體2的buffer cache裡找到，那麼執行個體1的lms程序會通過私網将這個block從執行個體2的cache擷取到執行個體1的cache，以避免physical reads，擷取過程中會出現gc cr block 2-way相關的等待事件，這就是cache fusion的基本功能，之後如果這個block沒有被任何一個執行個體更改，那麼執行個體1與執行個體2通路這個block就隻需從本地的buffer cache讀取(假設buffer cache足夠大，block未被flush出buffer cache)，本地讀取的情況下不會發生與gc相關的等待事件，對于同一個block隻需跨節點傳輸一次，這是一種比較理想的情況。
跨節點讀取除了這種以讀為主的情況外，還常見于以下場景：
執行個體1和執行個體2的buffer cache都含有這個block，t1時刻執行個體1修改了這個block，t2時刻執行個體2的會話讀取這個block時就會從執行個體1的buffer cache裡讀過來，過程中執行個體2會話統計裡就會觀察到gc cr block busy相關的等待事件。
—gc buffer busy acquire
沿用上面例子：執行個體1和執行個體2的buffer cache都含有某個block，t1時刻執行個體1修改了這個block，t2時刻執行個體2上的會話1讀取這個block，當這個讀取還沒有完成，執行個體2上的會話2也發起了讀取相同block的操作，這時會話2就會等在gc buffer busy acquire上。執行個體2同時發起的讀取相同block的會話數越多，我們就越容易觀察到gc buffer busy acquire等待。
—gc cr block busy
仍沿用上面例子：執行個體1和執行個體2的buffer cache都含有某個block，t1時刻執行個體1修改了這個block；t2時刻執行個體2上的會話1讀取這個block修改前的cr copy，因為cr copy需要通過應用undo record才能構造出來，且構造的過程中必須将改變記入到執行個體1的online redo，是以執行個體2會話1讀取的時候在可能會因為如下原因而發生gc cr block busy等待：
cr copy在執行個體1上構造過慢或者記入online redo過慢
gc buffer busy acquire與gc cr block busy有何聯系
從v$active_session_history裡取出某一時刻select t.* from sd.sys_parameter t where t.param_class in (:1 , :2 )語句【sql_id=2h21bq1mnc5kd】的等待，
圖6
可以看出在10:03:34.682這個時刻存在以下兩條session等待鍊：
之後又看了其它時刻的采樣結果(篇幅關系，不一一列出)，基本都是這個情況，是以判斷是gc cr block busy進一步導緻了gc buffer busy acquire，某一時刻對于同一個data block而言隻會有一個會話等在gc cr block busy事件上，其它會話都在等gc buffer busy acquire。這也可以解釋awr報告裡為何gc buffer busy acquire等待次數要遠多于gc cr block busy。至此關注重點集中到了gc cr block busy上。
定位修改源頭，模拟gc cr block busy等待
從gc cr block busy事件的定義上來看，執行個體2上的會話在執行select t.* from sd.sys_parameter t where t.param_class in (:1 , :2 )語句時之是以會遇到gc cr block busy等待，肯定是執行個體1上的會話對sd.sys_parameter表進行了dml操作，且這個修改操作涉及的記錄主要集中在93号資料檔案的65696号block上，但從開發人員處了解到sd.sys_parameter是一張配置表，平時不會有修改操作，口說無憑， 我們還是使用dbms_fga 包捕獲到了針對sd.sys_parameter表的修改操作，執行如下語句配置fga捕獲政策：
不出五分鐘就有結果了
圖7
很有規律的每30秒update一次，來自于執行個體1。既然update的頻率是30秒一次，select語句遇到的gc cr block busy、gc buffer busy acquire等待事件也應該是每隔30秒出現一波，但現實卻是分分秒秒都有這兩種等待，以下是從v$active_session_history統計出來的資訊：
圖8
為此在同版本的一套測試rac資料庫上進行了一組簡單的測試，過程中用到了三個session，
testnode 1上的session 1：對測試表進行200w次不間斷的select
testnode 1上的session 2：與session 1執行相同的操作，與session 1同時發起
testnode 2上的session 1：在testnode 1的兩個session運作過程中以每30秒一次的頻度update測試表中的一條記錄
testnode 1上的session 3：統計testnode 1 上兩會話的等待事件
先将要用到的腳本貼出來：
測試開始：
圖9
測試結果1：
testnode 1上的兩個session 分别執行耗時分别為118s、120s，統計結果顯示與它們同時執行的update語句并沒有帶來多大影響，gc cr block busy等待事件都在個位數，當然這也可能是因為測試環境裡模拟的并發量隻有2遠小于生産環境裡的實際并發數，再仔細想一下，每30秒update一次，120s的時間内update最多也就執行4次，也就是說循環select期間的至多遇到4次update，從testnode1上的會話統計資訊看，gc cr block busy分别為2、3，非常接近于4，是以推測這2次、3次的gr cr block busy等待應該正好發生在每次update過後的第一次select裡，從這以後到下一次update運作前的這段空檔期，不會再有gc cr block busy事件發生。而實際在生産環境表現出的症狀卻是每秒鐘都有gc cr block busy等待。
這個顯著的差異讓我對測試方法稍加調整，把 session 1 testnode 2執行語句改成update後過30秒再commit，調整後的測試過程如下：
圖10
測試結果2：
上述相鄰查詢間隔大概在1秒鐘，可以看出gc buffer busy acquire，gc cr block busy等待次數快速上升，增長的頻率與update的頻率(30秒一次)并沒有直接關系。至此測試結果與生産環境中的情況有點接近了，難道在生産環境也存在延時commit的情況？
找到生産環境裡update後沒有及時commit的證據
dba_fga_audit_trail視圖有一列sql_bind會記錄語句執行時的綁定變量資訊：
圖11
拿上圖的第一行來講在20160505 09:54:08時刻，将綁定變量代入得到完整的update語句是：
是以最簡單的方法就是實時監控dba_fga_audit_trail，每當觀察到dba_fga_audit_trail視圖新進來一條被審計到的sql及其對應的綁定變量後，立刻執行select param_value from sd.sys_parameter where param_code='ca_vcsms_time'，來觀察param_value字段何時變成綁定變量的值，如果一直沒有變化，那就證明沒有送出，通過這個方法，我們發現commit操作果然是在update之後的30秒才執行的，準确的說應該是在下一條update開始之前commit前一條update的修改結果。
還有一種能證明延時commit的方法是記錄下dba_fga_audit_trail. transactionid，然後到v$transaction根據xid查找是否存在對應記錄，若能找到就表明還未送出。
順便也驗證一下：parameter_code=’ca_vcsms_time’所在的記錄就位于争用最嚴重的file#:93/block#:65696裡
圖11-1
深入gc cr block busy
文章開頭處曾經介紹過其成因與block的cr copy在遠端執行個體上的構造過程及寫online redo過程有關。展開講，當執行個體1和執行個體2的buffer cache都含有某個block，t1時刻執行個體1修改了這個block，但沒有commit；t2時刻執行個體2上的會話1讀取這個block，讀取的大緻過程分解可以分解為以下幾個步驟：
1）執行個體2的lms向執行個體1的lms發起block 讀請求；
2）執行個體1的buffer cache裡已經存在了這個block修改後的最新副本b1’，執行個體1的 lms在本地的buffer cache裡根據b1’再複制出一個新的副本b1’’，此時b1’和b1’’的内容是完全相同的；
3）執行個體1的lms從undo segment裡找到undo record用來applied到b1’’上，把b1’’復原到修改前的狀态，記為b1；
4）這時執行個體1的buffer cache 裡包含了b1’，b1，其中b1是b1’修改前的内容。
5）利用undo record将b1’’復原到b1這一過程是會産生redo的，執行個體1 的lms程序通知lgwr程序把redo寫入online redolog，寫成功後才能進入下一步；
6）執行個體1上的lgwr通知執行個體1上的lms redo寫入完成，執行個體1上的lms将b1傳輸給執行個體2的lms；
7）執行個體2的lms将結果傳回給執行個體2上的會話1的server process。
我們通過如下的簡單測試可以大緻觀察到這個過程，還是在同版本的測試rac環境下進行：
圖12
---session 2 testnode 2: 記錄testnode 2上lms程序的初始統計值
圖13
---session 1 testnode 1；select測試表
select * from poweruser.t0505_1;
---session 2 testnode 2: 檢查testnode 2上lms程序的最新統計值
圖14
計算內插補點： 一個rac節點上有多個lms程序以負載均衡的方式被使用，本測試中正好是7897這個sid對應的lms程序被使用到
與前一次查詢結果相比：
圖15
計算內插補點：
cr blocks created：增加了1 <--- 因為poweruser.t0505_1表裡隻有一個塊是有資料的
data blocks consistent reads - undo records applied：增加了2 <--- 與v$transaction.used_urec值對應
redo entries：增加了1
redo size：增加了64
由此可以看出若遠端節點修改某個block後未送出，那麼本地節點去select遠端節點上的這個block時每次都會引發cr塊構造(cr blocks created)、 應用undo record(data blocks consistent reads - undo records applied)、生成redo(redo entries & redo size )等一系列動作，查詢未送出的block開銷還是比較大的，主要展現在遠端節點lms、lgwr程序的cpu使用率上升(之後會有詳細說明)，讀取undo block與寫入online redo時的io量增大。尤其是在本地節點高并發select 的時候這一開銷會無限放大。
本地節點select遠端節點cache裡未送出的資料塊開銷到底有多大
還是由實驗資料來說話：
(1) 遠端節點修改後及時送出，本地節點兩個session并發select同一張表
---session 1 on testnode2：執行對于測試表的修改并送出
---session 3 on testnode1：記錄會話統計初始值
@sess_1st.sql 1 14678 1 15251
---session 1 on testnode1 & session 2 on testnode1: 同時執行
set timing on
@circle_sel1.sql <---circle_sel1.sql和之前circle_sel.sql的差別在于執行次數從200w下調至30w，僅為了節省等待時間，更快得出結論
session 1 on testnode1的執行耗時：17.99s
session 2 on testnode1的執行耗時：17.72s
---session 3 on testnode1：輸出會話統計值(僅列出與gc相關的等待)
@sess_2nd.sql 1 14678 1 15251
圖16
(2) 遠端節點修改後未送出，本地節點兩個session并發select同一張表
---session 1 on testnode2：修改測試表但不送出
@circle_sel1.sql
session 1 on testnode1的執行耗時：485.89s
session 2 on testnode1的執行耗時：485.91s
圖17
附testnode1節點select執行期間testnode2上的lms、lgwr程序的cpu使用率
圖18
其中8585392是lgwr、5571040是lms
(3) 擴充一下，本地節點兩個session并發select不同的兩張表
---session 1 on testnode2：分别修改兩張測試表，都不送出
---session 1 on testnode1：30w次select表t0505_1
---session 2 on testnode1：30w次select表t0506
@circle_sel2.sql
session 1 on testnode1的執行耗時：501.94s
session 2 on testnode1的執行耗時：482.88s
圖19
測試結論：
對于(1)、(2)兩個場景可以看出遠端節點修改後未送出的場景下測出的select時長為485s遠遠大于送出情況下的17s，且後一種場景下遠端節點的lms、lgwr程序分别占用了1.9%和2.5%的cpu資源，對于32 cores的主機來說這兩個程序占去了約1.5 cores，況且現在僅僅是兩個并發的情況。
對于(3)場景而言，select兩張不同的表，仍然出現了各30w次的gc cr block busy等待，且耗時與(2)場景差不多。可見是否select相同的表不重要，關鍵在于遠端節點的構造cr block->flush redo這個過程是相當耗時的。
優化舉措
短期考慮：
1） 修改後及時送出，且修改的操作盡量與select操作放在同一個節點
2） 鑒于sd.sys_parameter是一張配置表，配置表裡的記錄應該保持相對穩定，是以将update的動作挪至建立的一張表進行
長遠考慮：
3）把sd.sys_parameter放到app緩存裡，避免過于頻繁從資料庫裡進行select
目前已經完成上述第1項優化，效果明顯。
這個案例告訴我們
cache fusion是一把雙刃劍，雖然能以節點間的通信來避免更多的實體讀，但我們也要避免節點間某些不合理的通信行為，比如對于同一個block的讀和寫分别在兩個節點進行，本文的案例和測試使我們認識到block跨節點傳輸所産生的開銷是如此之大。對于應用設計者而言應該認識到修改後不及時的送出在單節點環境下可能最多會引起row lock，但在多節點rac環境下，在節點間存在大量通信的場景下，會對性能産生不可估量的影響。
作者介紹 崔宏慧
上海移動dba，11g ocm，shoug成員，itpub部落格專家，oracle使用者組年輕專家。
<b></b>
<b>本文來自雲栖社群合作夥伴"dbaplus"，原文釋出時間：2016-05-31</b>