背景
Oracle資料庫的線上日誌包含已提交的和未提交的事務，但OGG只會將已提交的事務寫入到佇列檔案。因此，針對未提交的事務，特別是未提交的長事務，OGG會怎樣處理呢？
有些長事務是在批處理作業中，需要幾個小時才能執行完成，比如晚上跑批的作業。這種情況，OGG會從這些事務一執行就開始讀取線上日誌，但這些事務可能會持續很久，從而線上日誌也會切換到歸檔日誌中，這期間也可能會有其它事務在執行和提交，如果長事務一直未提交，一旦OGG抽取程式有重啟，歸檔日誌又因為定期的rman備份而刪除，此時該怎麼辦呢？
針對以上情況，OGG有2種處理方式，第一種就是使用正常恢復歸檔的方式，即恢復OGG需要的所有歸檔日誌，可能是從長事務開始的那個歸檔開始，這樣OGG能事務開始的檢查點開始解析；第二種方式就是使用Bounded Recovery的方式，下面的內容將討論這種方式。
簡單來說，BR（Bounded Recovery ）預設的設定是4小時，即每4小時OGG抽取程式會做一個檢查點，在每個檢查點的時間點上，OGG會檢查長事務，並將超過4小時的長事務的當前狀態寫入到磁碟，預設儲存在OGG安裝目錄的BR目錄下。在每個BR的間隔點，這個操作會一直持續，直到事務提交，或事務回滾。
下面是官方文件的描述：
使用磁碟持久儲存資料，用於恢復長事務，讓抽取程式可以確保捕獲效能（雖然只有在極端情況下才會發生捕獲延遲）。如果抽取程式停止時，有些事務的開始時間遠在這個時間點之前，那麼系統需要佔用大量的日誌空間，也有可能這些日誌檔案不再儲存或被刪除。而且，重新從一個很早的日誌檔案開始讀取事務，這種做法還是有些問題的，因為這些日誌檔案中的其它事務已經被解析並被寫入到佇列檔案。如果通過持久化資料能恢復這些長事務的狀態，那麼就可以消除這個往返讀取的工具。極端的情況下，如果有多個長事務，如果每個事務都要求從起點重新讀取，那麼OGG的捕獲效能將大大降低。
在本示例中，我們將BR的間隔設定為20分鐘，然後執行一個insert語句，但不提交。此時，抽取程式會從線上日誌的某個點開始讀取，線上日誌的序號為：#14878。OGG抽取程式的引數新增一行：
BR BRINTERVAL 20M
然後我們切換幾組日誌，備份並刪除序號為14878的日誌檔案。我們可以看到每隔20分鐘，BR就會被處理，此時，長事務的狀態資訊及資料就會被寫入到磁碟上。
即使磁碟上沒有對應的歸檔日誌檔案，抽取程式也不會去讀取這些日誌，而是直接從磁碟上儲存的資料進行恢復，如果事務提交，則OGG會直接將BR目錄下的資料寫入到佇列中。
測試
測試步驟如下：
執行下面的INSERT語句，但不提交，用於測試長事務的場景：
SQL> insert into myobjects select object_id,object_name,object_type from dba_objects;
75372 rows created.
通過infor ext1檢查當前讀取的線上日誌序號，本測試中是14878
GGSCI (ol66) 2> info ext1 EXTRACT EXT1 Last Started 2014-06-21 18:07 Status RUNNING Checkpoint Lag 00:00:00 (updated 00:00:08 ago) Process ID 15190 Log Read Checkpoint Oracle Redo Logs 2014-06-21 18:10:21 Seqno 14878, RBA 5936128 SCN 0.9137531 (9137531) |
使用SEND EXTRACT SHOWTRANS檢視是否有事務是開啟狀態：
GGSCI (ol66) 4> send ext1 showtrans Sending SHOWTRANS request to EXTRACT EXT1 … Oldest redo log file necessary to restart Extract is: Redo Log Sequence Number 14878, RBA 116752 ———————————————————— XID: 10.16.1533 Items: 75372 Extract: EXT1 Redo Thread: 1 Start Time: 2014-06-21:18:10:14 SCN: 0.9137521 (9137521) Redo Seq: 14878 Redo RBA: 116752 Status: Running |
INFO EXTRACT SHOWCH 會顯示抽取程式檢查點的更多資訊，包括當前事務（日誌）中的讀取點，寫入佇列檔案的位置等。
下面的示例中，第一個檢查點是抽取程式啟動時的讀取點：14861，接著是最早未提交事務的讀取點是14878，SCN：9137521，最後是抽取程式當前的日誌讀取檢查點，序號仍然是14878，但SCN是9137612，說明在這個未提交的事務之後，DB已經有一些其它操作。
GGSCI (ol66) 5> info ext1 showch EXTRACT EXT1 Last Started 2014-06-21 18:07 Status RUNNING Checkpoint Lag 00:00:00 (updated 00:00:06 ago) Process ID 15190 Log Read Checkpoint Oracle Redo Logs 2014-06-21 18:11:41 Seqno 14878, RBA 5977088 SCN 0.9137612 (9137612) Current Checkpoint Detail: Read Checkpoint #1 Oracle Redo Log Startup Checkpoint (starting position in the data source): Thread #: 1 Sequence #: 14861 RBA: 5918224 Timestamp: 2014-06-21 16:49:33.000000 SCN: 0.9129707 (9129707) Redo File: /u01/app/oracle/fast_recovery_area/GGATE1/archivelog/2014_06_21/o1_mf_1_14861_9tbo7pys_.arc Recovery Checkpoint (position of oldest unprocessed transaction in the data source): Thread #: 1 Sequence #: 14878 RBA: 116752 Timestamp: 2014-06-21 18:10:14.000000 SCN: 0.9137521 (9137521) Redo File: /u01/app/oracle/oradata/ggate1/redo03.log Current Checkpoint (position of last record read in the data source): Thread #: 1 Sequence #: 14878 RBA: 5977088 Timestamp: 2014-06-21 18:11:41.000000 SCN: 0.9137612 (9137612) Redo File: /u01/app/oracle/oradata/ggate1/redo03.log Write Checkpoint #1 GGS Log Trail Current Checkpoint (current write position): Sequence #: 3 RBA: 8130790 Timestamp: 2014-06-21 18:11:44.414364 Extract Trail: ./dirdat/zz Trail Type: RMTTRAIL |
大約20分鐘之後，我們繼續使用showch，看看與前面的命令相比，輸出有哪些差異。可以看到，當前讀取的線上日誌序號已經變為14884（以前是14878）。
但恢復檢查點仍然沒有變化，與上一個命令執行結果相同。
GGSCI (ol66) 2> info ext1 showch EXTRACT EXT1 Last Started 2014-06-21 18:07 Status RUNNING Checkpoint Lag 00:00:00 (updated 00:00:04 ago) Process ID 15190 Log Read Checkpoint Oracle Redo Logs 2014-06-21 18:40:34 Seqno 14884, RBA 72704 SCN 0.9139491 (9139491) Current Checkpoint Detail: Read Checkpoint #1 Oracle Redo Log Startup Checkpoint (starting position in the data source): Thread #: 1 Sequence #: 14861 RBA: 5918224 Timestamp: 2014-06-21 16:49:33.000000 SCN: 0.9129707 (9129707) Redo File: /u01/app/oracle/fast_recovery_area/GGATE1/archivelog/2014_06_21/o1_mf_1_14861_9tbo7pys_.arc Recovery Checkpoint (position of oldest unprocessed transaction in the data source): Thread #: 1 Sequence #: 14878 RBA: 116752 Timestamp: 2014-06-21 18:10:14.000000 SCN: 0.9137521 (9137521) Redo File: /u01/app/oracle/oradata/ggate1/redo03.log Current Checkpoint (position of last record read in the data source): Thread #: 1 Sequence #: 14884 RBA: 72704 Timestamp: 2014-06-21 18:40:34.000000 SCN: 0.9139491 (9139491) Redo File: /u01/app/oracle/oradata/ggate1/redo03.log |
通過上面的命令，我們看到了BR檢查點的相關資訊，前面我們把BR間隔從預設4小時改為20分鐘，因此，每隔20分鐘（本示例中是：18：07，18：27，18：47...），當前的的狀態資訊會被抽取程式寫入到磁碟上的BR目錄。
因此，我們看到在18:27的BR間隔時間點，BR將線上日誌14881的資訊持久到磁碟上，如果這個時候extract有錯誤或重啟，extract不再需要從早於14881序號的redo或歸檔裡讀取資料。
BR Previous Recovery Checkpoint: Thread #: 0 Sequence #: 0 RBA: 0 Timestamp: 2014-06-21 18:07:35.982719 SCN: Not available Redo File: BR Begin Recovery Checkpoint: Thread #: 0 Sequence #: 14878 RBA: 116752 Timestamp: 2014-06-21 18:10:14.000000 SCN: 0.9137521 (9137521) Redo File: BR End Recovery Checkpoint: Thread #: 1 Sequence #: 14881 RBA: 139776 Timestamp: 2014-06-21 18:27:38.000000 SCN: 0.9138688 (9138688) Redo File: |
在BR目錄中我們可以看到抽取程式ext1生成的一些檔案：
GGSCI (ol66) 4> info ext1 EXTRACT EXT1 Last Started 2014-06-21 18:07 Status RUNNING Checkpoint Lag 00:00:00 (updated 00:00:06 ago) Process ID 15190 Log Read Checkpoint Oracle Redo Logs 2014-06-21 18:41:35 Seqno 14884, RBA 131072 SCN 0.9139583 (9139583) |
GGSCI (ol66)
GGSCI (ol66) 3> shell ls -l ./BR/EXT1 total 20 -rw-r—– 1 oracle oinstall 65536 Jun 21 18:27 CP.EXT1.000000015 drwxr-x— 2 oracle oinstall 4096 Jun 19 17:07 stale |
此時，如果我們刪除14878的歸檔日誌會怎樣呢？因為BR檢查點已經將包含長事務的日誌序號為14878的資訊寫入到磁碟，extract程式將不再需要這些舊的歸檔檔案。
為了測試這個功能，我們將14878歸檔備份之後刪除，記住，這個歸檔序號是長事務開始時的日誌序號。
RMAN> backup archivelog sequence 14878 delete input; Starting backup at 21-JUN-14 using target database control file instead of recovery catalog allocated channel: ORA_DISK_1 channel ORA_DISK_1: SID=24 device type=DISK channel ORA_DISK_1: starting archived log backup set channel ORA_DISK_1: specifying archived log(s) in backup set input archived log thread=1 sequence=14878 RECID=30497 STAMP=850846396 channel ORA_DISK_1: starting piece 1 at 21-JUN-14 channel ORA_DISK_1: finished piece 1 at 21-JUN-14 piece handle=/u01/app/oracle/fast_recovery_area/GGATE1/backupset/2014_06_21/o1_mf_annnn_TAG20140621T234659_9tcb7msp_.bkp tag=TAG20140621T234659 comment=NONE channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01 channel ORA_DISK_1: deleting archived log(s) archived log file name=/u01/app/oracle/fast_recovery_area/GGATE1/archivelog/2014_06_21/o1_mf_1_14878_9tbpowlm_.arc RECID=30497 STAMP=850846396 Finished backup at 21-JUN-14 |
好，我們現在來提交這個交易。
SQL> commit;
Commit complete.
在抽取程式ext1的日誌報告中，可以看到長事務的資訊提示，包括事物xid，記錄數等，也包含BR檢查點的資訊，可以看到每20分鐘，日誌中就會有BR寫入檢查點的提示資訊，而且檢查點的SCN隨著時間也在增長。
GGSCI>view report ext1 2014-06-21 18:17:42 WARNING OGG-01027 Long Running Transaction: XID 10.16.1533, Items 75372, Extract EXT1, Redo Thread 1, SCN 0.9137521 (9137521), Redo Seq #14878, Redo RBA 116752. 2014-06-21 18:27:41 INFO OGG-01971 The previous message, ‘WARNING OGG-01027′, repeated 1 times. 2014-06-21 18:27:41 INFO OGG-01738 BOUNDED RECOVERY: CHECKPOINT: for object pool 1: p23540_extr: start=SeqNo: 14878, RBA: 116752, SCN: 0.9137521 (9137521), Timestamp: 2014-06-21 18:10:14.000000, end=SeqNo: 14881, RBA: 139776, SCN: 0.9138688 (9138688), Timestamp: 2014-06-21 18:27:38.000000, Thread: 1. 2014-06-21 18:47:50 INFO OGG-01738 BOUNDED RECOVERY: CHECKPOINT: for object pool 1: p23540_extr: start=SeqNo: 14885, RBA: 144912, SCN: 0.9139983 (9139983), Timestamp: 2014-06-21 18:47:47.000000, Thread: 1, end=SeqNo: 14885, RBA: 145408, SCN: 0.9139983 (9139983), Timestamp: 2014-06-21 18:47:47.000000, Thread: 1. 2014-06-21 19:07:59 INFO OGG-01738 BOUNDED RECOVERY: CHECKPOINT: for object pool 1: p23540_extr: start=SeqNo: 14889, RBA: 176144, SCN: 0.9141399 (9141399), Timestamp: 2014-06-21 19:07:56.000000, Thread: 1, end=SeqNo: 14889, RBA: 176640, SCN: 0.9141399 (9141399), Timestamp: 2014-06-21 19:07:56.000000, Thread: 1. |
最後，記住一點：如果使用BR預設的4小時，則在磁碟上至少要儲存過去8小時的歸檔日誌，以便滿足任何長事務的解析要求。