簡單的幾條Insert語句引起的邏輯Standby應用延遲的診斷

一個邏輯Standby的庫，執行在Redhat as4u4_x86_64的平臺上，資料庫版本10.2.0.2。主庫執行的作業系統平臺和資料庫版本跟Standby庫一致，執行在最大效能模式，使用 LGWR ASYNC方式傳Redo到邏輯Standby庫。邏輯Standby庫使用Apply Immedite方式進行實時應用。因為這個庫的壓力很小，所以Standby庫和主庫之間的資料同步時間非常小，一般都在分鐘級別以內，但這次因為一個 每分鐘才執行幾次的簡單Insert語句卻能引起Standby Apply的延遲，確實有些不同尋常，下面來看看到底發生了什麼。[@more@]上午，收到報警郵件，說邏輯Standby庫的Apply跟主庫之間間隔已經有10分鐘了，這說明資料同步出現問題。這種問題在邏輯Standby庫的使用中經常碰到了，比如主庫一句SQL更新了大批次的資料，那Redo傳到Standby庫後，會被解析成一條條SQL來進行執行，會導致Apply變慢；或者因為某些原因導致Apply停掉，同樣也會出現延遲；或者Standby庫負載過高，導致Apply變慢，也會延遲等等。但經過一個個的排查和確認後，上面的問題一一被否決，而且延遲變得越來越大。Apply還在進行，但是非常緩慢，同時資料庫的負載明顯升高。
那首先來看看Standby庫在幹啥吧，透過查詢v$session_wait檢視，看到幾個很明顯的正在被APPLY的SQL要麼在等待latch: cache buffers chains，要麼在等待db file sequential read，從這些事件來看跟發生大量全表掃描的的等待事件十分相似，那就來看看這些SQL導致是在幹些什麼吧（以下SQL中的所有表名、欄位等全部使用替換過的命名）。SQL原文如下：
select "B" into loc_c from "TEST"."BEAR" where "A" = '264312' for update;
檢視這個SQL的執行計劃，果然是一個全表掃描，怪不得會出現上面那麼多的等待事件了。看看錶的結構，這個表上居然沒有任何的索引或者主鍵，於是把開發同事抓過來，確認A欄位應該是表的主鍵，當初建立表的時候忘記加主鍵了，於是為這個表建立了一個唯一索引，然後再來觀察Standby上的等待事件，原先的等待事件都沒有了，SQL Apply的速度明顯加快，一會就跟主庫的同步時間縮短到正常範圍。
本來故事到這裡就結束了，但跟開發人員交流中得知這個表是一個日誌表，也就是說資料永遠只會插入，只有碰見問題需要查詢的時候才會來手工的查詢這個表裡的資料，而且根本不會去弄個for update的查詢去加一個鎖上去。
這問題就來了，跟開發再三確認，開發拿腦袋擔保說前臺引用只有INSERT操作，那這些for update的SQL哪裡冒出來的呢？
最簡單的辦法就是使用Logminer去挖掘主庫的日誌，看看主庫當時到底記錄了什麼東西到REDO。挖掘出來的結果是這樣的（為了方便閱讀，去掉了一些雙引號；為了節省篇幅，CLOB字串中很多abcabc的字元被---符號替代）：
set transaction read write;

insert into "TEST"."BEAR"("A","B") values ('264298',EMPTY_CLOB());

DECLARE
loc_c CLOB;
buf_c VARCHAR2(6168);
loc_b BLOB;
buf_b RAW(6168);
loc_nc NCLOB;
buf_nc NVARCHAR2(6168);
BEGIN
select ""B"" into loc_c from ""TEST"".""BEAR"" where ""A"" = '264298' for update;
buf_c := 'abcabc--------abcabcabca';
dbms_lob.write(loc_c, 4066, 1, buf_c);
END;

DECLARE
loc_c CLOB;
buf_c VARCHAR2(6168);
loc_b BLOB;
buf_b RAW(6168);
loc_nc NCLOB;
buf_nc NVARCHAR2(6168);
BEGIN
select ""B"" into loc_c from ""TEST"".""BEAR"" where ""A"" = '264298' for update;
dbms_lob.trim(loc_c, 1998);
END;

commit;

從上面的結果可以看出來，開發說的一個簡單的Insert操作，卻對應了一堆的SQL REDO，而且自己測試的結果也證明了這點，這說明開發說的是正確的，問題出現在有CLOB欄位插入時候ORACLE記錄REDO日誌的方式，ORACLE是這麼來記錄REDO的：
1、 先設定事務為可讀寫
2、 執行INSERT語句，但是CLOB欄位會先插入一個EMPTY_CLOB()來進行初始化
3、 把實際要插入CLOB中的內容呼叫dbms_lob.write來完成
4、 呼叫dbms_log.trim把clob列截斷到實際插入的字串的長度
5、 提交事務

但是，並不是所有的CLOB的插入全部是轉換成上面的格式，其實我自己測試的時候是先得到的下面的格式的：
set transaction read write;

insert into "TEST"."BEAR"("A","B") values ('264355',EMPTY_CLOB());

update "TEST"."BEAR" set "B" = 'abcabc----bcabca' where "A" = '264355' and ROWID = 'AAAMvOAAEAAATzuAAA';

commit;
跟上面不同的是設定CLOB值的時候，是直接使用UPDATE來做的，而不是呼叫DBMS的包實現的，那麼為什麼相同的SQL會有兩種不同的方式來記錄REDO呢？

其實得到這兩個簡單的REDO花了不少力氣的，過程就不詳細描述了，這裡只描述一下方法和步驟：
1、 建立一個表BEAR，包含兩列，其中一個是順序號--A，一個是CLOB欄位--B
2、 隨便插入一行值，假設a=1,b=’abc’,然後透過update bear set b=b||b的方式，使得插入的CLOB欄位值變得足夠大，基本上超過4000個位元組就足夠了，假設這裡是5000個位元組長
3、 然後建立一個SEQUENCE，用來生成A列的值
4、 寫一個迴圈，從1迴圈到5000（對應上面的位元組長度），然後開始insert into bear select sequence.nextval,substr(b,1,5000-i) from bear where a=1，這裡的意思就是透過插入的第一行，來生成其他的插入資料，其中變化的地方就在CLOB列的插入，讓它的長度不停的減小。
5、 完成後挖掘上面這段日誌，會發現SQL REDO記錄的不同格式發生在CLOB長度為1982到1983之間的時候，CLOB的長度>=1983的時候，生成的REDO是第一種格式，使用DMBS的格式；CLOB長度<=1982的時候，生成的REDO是第二種格式，直接使用UPDATE來更新的方式。

1982和1983，搞不明白了，為什麼是一個三不沾的數字？為什麼不是因為UPDATE的時候的字串長度最大為4000，超過4000不能表示，所以4000應該是分界點啊；或者因為字符集的問題，一個字元佔多個位，那也應該是4000/2或者UTF-8的時候是4000/3啊。想破了腦袋，最後還是在METALINK上找到了答案（ML: 66431.1）。

LOB欄位的儲存分為in line和out line，這個很多人都清楚，而且有個引數可以設定的，就是建立表的時候設定LOB的ENABLE STORAGE IN ROW或者DISABLE STORAGE IN ROW，也就是說，LOB是否跟其他對應的行資料一起存放，還是單獨的開一個LOB型別的SEGMENT來存放。但即使你設定的是in line儲存的，那LOB也不一定就和行資料一起儲存在表的SEGMENT中的，因為LOB一般都很大，這麼儲存是不合理的，那麼ORACLE就劃分了一條分界線，注意，重點就在這條分界線了。當你設定out line儲存的時候，LOB直接儲存到單獨的LOB SEGMENT；當設定in line儲存的時候，以3964為分界線，長度小於或者等於3964的，那就是真正的in line儲存，LOB資料和行其他資料存放在一起，長度大於3964的時候，即使設定是in line儲存的，但ORACLE還是會把資料存放到單獨的LOG SEGMENT中去。
3964/2=1982，到這裡終於搞明白為什麼這裡會是日誌記錄格式的分界點，也就是說對於所有的LOB跟行資料一起儲存的，ORACLE就使用UPDATE更新的方式來記錄LOB相關的REDO；對於LOB是單獨SEGMENT儲存的，那就是使用DBMS包更新的方式。這麼設計應該跟前面的猜測是一致的，因為VARCHAR最大支援的字串長度就是4000，所以大於4000的話，單獨的UPDATE沒辦法表示要插入的CLOB的正確的值，所以就需要使用DBMS的方式來更新。
那麼還有一個問題，為什麼不是以VARCHAR的長度限制4000為分割點呢？METALINK上還說了這麼一句：
When a LOB is stored out-of-line in an 'enable storage in row' LOB column between 36 and 84 bytes of control data remain in-line in the row piece.
也就是說，當設定為in line的方式儲存LOB的時候，萬一因為LOB太大需要out line方式來儲存，那麼這時候就需要在原先的行空間中保留36到84位元組的控制資料。當LOB真的是in line儲存的時候，應該是以VARCHAR的替代方式來儲存的，而VARCHAR最大隻能存4000，然後保留36個位元組的控制資料的空間，那麼也就是說in line儲存的LOG的最大長度只能有3964。

到這裡為止，這一切都全部串起來了。還剩最後一個疑問，既然METALINK上說當該in line的LOB被out line儲存的時候，才會保留36-84位元組的空間給控制資訊使用，那還是應該in line儲存的時候能儲存到4000位元組，而不是隻能儲存到3964位元組才對啊。下面透過另一個方法來證明下其實METALINK說的不是那麼準確的。
1、隨便插入一行資料，LOB欄位插入為空 ，然後把這個BLOCK DUMP的結果如下：
col 0: [ 2] c1 03
這說明空的LOB是不佔用空間的，接下來UPDATE LOB欄位為一個字元“a”。
2、然後再次DUMP，結果如下：
col 0: [ 2] c1 03
col 1: [38]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 02 00 12 09 00 00
00 00 00 00 02 00 00 00 00 00 01 00 61
可以看到，除了插入的字元“a”的ASCII碼61以外，LOB列還多了36個控制字元，一共長度是38個字元，這也正好說明了為什麼in line的時候LOB的長度最大隻能到3964而不是到4000。
3、然後UPDATE LOB欄位長度到1983，讓它剛剛從in line跳到out line，這個時候DUMP結果如下：
col 0: [ 2] c1 03
col 1: [40]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 03 00 14 05 00 00
00 00 00 0f 7e 00 00 00 00 00 02 01 00 e0 01
這個說明只要是out line儲存的，那至少是需要40個位元組的控制字元空間的
4、然後不停的update bear set b=b||b where a=1來膨脹LOB的大小，然後再次DUMP，結果如下：
col 0: [ 2] c1 03
col 1: [84]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 00 00 40 05 00 00
00 3e 95 0a ec 00 00 00 00 00 02 01 00 a4 4c 01 00 a4 5c 01 00 a4 6c 01 00
a4 7c 01 00 a4 8c 01 00 a4 2c 01 00 a4 9c 01 00 a4 3c 01 00 a5 28 01 00 a5
09 01 00 a5 19 01 00 a5 29
從上面的結果可以看到，這個時候，控制字元佔用的空間已經膨脹到了84個位元組了。
那麼當in line儲存LOB的時候，只要LOB不為空，那麼就會有36個位元組的控制字元，所以LOB最大隻能存放3964位元組的內容；當LOB擴張到需要out line儲存的時候，控制字元才會超過36個位元組的大小，並且隨著LOB的膨脹而膨脹，最終膨脹到84位元組。

寫總結前先引用一段Data Guard Concepts and Administration 10g Release 2 (10.2)中的一段話，說明了SQL產生的REDO在邏輯Standby上應用的情況：
1、If a table has a primary key defined, then the primary key is logged along with the modified columns as part of the UPDATE statement to identify the modified row.
2、In the absence of a primary key, the shortest nonnull unique-constraint/index is logged along with the modified columns as part of the UPDATE statement to identify the modified row.
3、In the absence of both a primary key and a nonnull unique constraint/index, all columns of bounded size are logged as part of the UPDATE statement to identify the modified row. In other words, all columns except those with the following types are logged: LONG, LOB, LONG RAW, object type, and collections.

在這個案例中，因為所有的SQL只是簡單的插入，所以表上沒有建主鍵或者任何索引（插入快嘛），但偏偏因為CLOB的特殊性，導致主庫上的插入的SQL在邏輯Standby庫上會被拆分成包含select …. For update或者update …的格式來進行LOB欄位的更新，那麼如果這個表上沒有任何索引或者主鍵，這些for update或者update就會變成一個全表掃描，而且隨著資料量的不斷增加，掃描的成本越來越高，最終導致SQL Apply越來越慢，從而引起了主備庫不同步的問題。