一、問題描述：
2013年4月14日中午12點左右生產環境執行資料庫版本升級期間根據需要停止XX1庫和XX2庫OGG 同步抽取程式時遇長事務，無法用正常命令停止，執行 forcestop 後重啟程式報 OGG-00446 錯誤，無法啟動。錯誤如下：
2013-04-14 19:30:28 ERROR OGG-00446 Opening ASM file+FRA/bjschxsb/1_7125_796652962.dbf in DBLOGREADER mode: (308) ORA-00308: cannot open archived log'+FRA/bjschxsb/1_7125_796652962.dbf'
ORA-17503: ksfdopn:2 Failed toopen file +FRA/bjschxsb/1_7125_796652962.dbf
ORA-15173: entry'1_7125_796652962.dbf' does not exist in directory 'bjschxsb' Not able to establish initial position for sequence 7125, rba 339291664.
2013-04-14 19:30:28 ERROR OGG-01668 PROCESS ABENDING.

二、問題原因：
XX1庫和XX2庫的 Extract 程式在執行 forcestop 停止前（瞬間）正在處理既未提交也未回滾的長時間執行事務，重新啟動 Extract 程式後需要執行 Extract 程式恢復。
1、XX1庫
停止 XX1庫 Extract 程式時，正在處理的長事務為：
2013-04-14 11:51:46 WARNING OGG-01027 Oracle GoldenGate Capture for Oracle,esb_cx7.prm: Long Running Transaction:XID 561.10.31284,Items 0, Extract ESB_CX7, Redo Thread 1, SCN 3098.1568409621 (13307377092629),Redo Seq #7125, Redo RBA 339291664.

     截止目前該事務在資料庫中仍在進行：
SQL> select t.addr,t.XIDUSN,t.XIDSLOT,t.XIDSQN,t.START_DATEfrom gv$transaction t;
ADDR                XIDUSN    XIDSLOT     XIDSQN START_DATE
---------------- ---------- ---------- ----------------------------
070000084724BB90       561         10      31284 09-APR-13
SQL> select t.PREV_SQL_ID,t.SQL_ID from gv$session t wheret addr='070000084724BB90';

PREV_SQL_ID SQL_ID
------------- -------------
9m7787camwh4m
SQL> select sql_text from gv$sqltext t where t.SQL_ID = '9m7787camwh4m';
SQL_TEXT
----------------------------------------------------------------
begin :id := sys.dbms_transaction.local_transaction_id; end;
begin :id := sys.dbms_transaction.local_transaction_id; end;
begin :id := sys.dbms_transaction.local_transaction_id; end;
begin :id := sys.dbms_transaction.local_transaction_id; end;

該事務是由一臺 IP 地址為 162.16.220.70 的機器，透過 PL/SQL dev 工具於 2013 年 4 月 9 日發起，使用資料庫使用者是HX_SJZ，該事務至今未提交也未回滾。需要注意的是 HX_SJZ 使用者許可權已於 2013 年4月1日開始收回，該主機使用該使用者從3月28日用該使用者建立的 session 至今未斷開。
selectt.SID,t.SERIAL#,t.SCHEMA#,t.SCHEMANAME,t.OSUSER,t.MACHINE,t.PORT,t.TERMINAL,t.PROGRAM from gv$session t where taddr='070000084724BB90';
        SID   SERIAL#    SCHEMA# SCHEMANAMEOSUSER     MACHINE                    PORT TERMINAL   PROGRAM
---------- -------------------- ---------- ---------- -------------------- ---------- ----------------------------------------
      3351        107         77 HX_SJZ     css5      WORKGROUP\CSS-PC          53796CSS-PC     plsqldev.exe
bjschxdbsb01:/u01/app/grid/diag/tnslsnr/bjschxdbsb01/listener/trace$catlistener.log | grep css5 | grep 162.16.220.70 > /home/grid/listener.bak_20130414 sqldev.exe)(HOST=CSS-PC)(USER=css5)))* (ADDRESS=(PROTOCOL=tcp)(HOST=162.16.220.70)(PORT=53313)) * establish *bjschxsb * 0
28-MAR-2013 23:26:06 *(CONNECT_DATA=(SERVICE_NAME=bjschxsb)(GLOBAL_NAME=bjschxsb)(CID=(PROGRAM=D:\Program?Files\PLSQL?Developer\plsqldev.exe)(HOST=CSS-PC)(USER=css5)))* (ADDRESS=(PROTOCOL=tcp)(HOST=162.16.220.70)(PORT=53796)) * establish *bjschxsb * 0
28-MAR-2013 23:34:51 *(CONNECT_DATA=(SERVICE_NAME=bjschxsb)(GLOBAL_NAME=bjschxsb)(CID=(PROGRAM=D:\Program?Files\PLSQL?Developer\plsqldev.exe)(HOST=CSS-PC)(USER=css5)))* (ADDRESS=(PROTOCOL=tcp)(HOST=162.16.220.70)(PORT=53920)) * establish *bjschxsb * 0
28-MAR-2013 23:36:37 *(CONNECT_DATA=(SERVICE_NAME=bjschxsb)(GLOBAL_NAME=bjschxsb)(CID=(PROGRAM=D:\Program?Files\PLSQL?Developer\plsqldev.exe)(HOST=CSS-PC)(USER=css5)))* (ADDRESS=(PROTOCOL=tcp)(HOST=162.16.220.70)(PORT=53944)) * establish *bjschxsb * 0
重啟 XX1庫上的 Extract 程式後，需要使用thread 1, seq 7125-7152 歸檔日誌，而 seq 7125 歸檔正好已被刪除，這就是報錯的原因。
Recovery Checkpoint (position of oldestunprocessed transaction in the data source):
    Thread #: 1
    Sequence #: 7125
    RBA: 339291664
    Timestamp: 2013-04-09 15:18:13.000000
    SCN: 3098.1568409621 (13307377092629)
    Redo File: Not Available
Current Checkpoint (position of last recordread in the data source):
    Thread #: 1
    Sequence #: 7152
    RBA: 253142788
    Timestamp: 2013-04-14 11:59:29.000000
    SCN: 3099.705644312 (13310809294616)
    Redo File: +DATA/bjschxsb/onlinelog/redo01b
2 、 XX2庫分析
停止 XX2庫 Extract 程式時正在處理的長事務為

select t.addr,t.XIDUSN,t.XIDSLOT,t.XIDSQN,t.START_DATE from gv$transaction t;

ADDR XIDUSN XIDSLOT XIDSQN START_DAT
---------------- ---------- ---------- ---------- ---------
0700000405B10488 173 30 6643 10-APR-13

截止目前該事務在資料庫中仍在進行：
SQL> selectt.SID,t.SERIAL#,t.SCHEMA#,t.SCHEMANAME,t.OSUSER,t.MACHINE,t.PORT,t.TERMINAL,t.PROGRAMfrom gv$session t where taddr='0700000405B10488';
SID SERIAL# SCHEMA# SCHEMANAMEOSUSER MACHINE PORT TERMINAL PROGRAM
---------- -------------------- ---------- ---------- -------------------- ---------------------------------------- ------------------------------
2520 19683 98 SJCK oracle bjschxdbcx03 0 UNKNOWN )

    透過該事務正在進行的 sql 以及上一個 sql語句推測，該事務可能由於 Oracle 自動重新整理物化檢視的內部job發起，不會帶來業務資料變化。
SQL> selectt.PREV_SQL_ID,t.SQL_ID from gv$session t where taddr='0700000405B10488';
PREV_SQL_ID   SQL_ID
--------------------------
76cckj4yysvua 6x5246x8jk7wj

SQL> select sql_textfrom gv$sqltext t where t.SQL_ID = '76cckj4yysvua' order by t.PIECE;
SQL_TEXT
----------------------------------------------------------------
select time_mp, scn,num_mappings, tim_scn_map from smon_scn_time where scn =    (select max(scn) from smon_scn_time wherescn <= :1)
select time_mp, scn,num_mappings, tim_scn_map from smon_scn_time where scn =    (select max(scn) from smon_scn_time wherescn <= :1)
select time_mp, scn,num_mappings, tim_scn_map from smon_scn_time where scn =    (select max(scn) from smon_scn_time wherescn <= :1)
select time_mp, scn,num_mappings, tim_scn_map from smon_scn_time where scn =    (select max(scn) from smon_scn_time wherescn <= :1)

SQL> select sql_text fromgv$sqltext t where t.SQL_ID = '6x5246x8jk7wj' order by t.PIECE;

/* MV_REFRESH (MRG) */MERGE INTO "SJCK"."SE_GES_NSDSEWYYS2" "SN
A$" USING ( WITH"TMPDLT$_SE_GES_NSDSEWYYS1" AS ( SELECT /*+ RE
SULT_CACHE(LIFETIME=SESSION)*/ "MAS$"."RID$" "RID$" ,"MAS$"."N
SDEHJ","MAS$"."SDNF", "MAS$"."ZRRDZDAH",         DECODE("MAS$".
"OLD_NEW$$",'N', 'I', 'D') "DML$$",        "MAS$"."OLD_NEW$$"
"OLD_NEW$$","MAS$"."TIME$$" "TIME$$","MAS$"."DMLTYPE$$" "DMLTY
PE$$" FROM (SELECT "MAS$".*,   MIN("MAS$"."SEQ$$") OVER(PARTIT
ION BY"MAS$"."RID$") "MINSEQ$$",   MAX("MAS$"."SEQ$$") OVER(PA
RTITION BY"MAS$"."RID$") "MAXSEQ$$"   FROM (SELECT CHARTOROWID
("MAS$"."M_ROW$$")RID$ , "MAS$"."NSDEHJ", "MAS$"."SDNF","MAS
$"."ZRRDZDAH" , DECODE("MAS$".OLD_NEW$$, 'N','I', 'D') DML$$,
"MAS$"."DMLTYPE$$""DMLTYPE$$", "MAS$"."SEQUENCE$$" "SEQ$$","MA
S$"."OLD_NEW$$""OLD_NEW$$", "MAS$"."SNAPTIME$$""TIME$$" FROM
"SJCK"."MLOG$_SE_GES_NSDSEWYYS1""MAS$"   WHERE"MAS$".SNAPTIME$

恢復該資料庫上的 Extract 程式需要用到歸檔日誌 thread 3, seq 5862-6105,從 5862 開始的相當一部分歸檔日誌已被刪除，因此會報找不到歸檔。
Recovery Checkpoint (position of oldest unprocessed transaction in thedata source):
    Thread #: 3
    Sequence #: 5862
    RBA: 18504720
    Timestamp: 2013-04-10 01:00:18.000000
    SCN: 3098.1717076309 (13307525759317)
    Redo File: Not Available
Current Checkpoint (position of last recordread in the data source):
    Thread #: 3
    Sequence #: 6105
    RBA: 39127568
    Timestamp: 2013-04-14 11:58:38.000000
    SCN: 3099.2202080974 (13312305731278)
Redo File: +DATA/bjschxcx/onlinelog/redo12b
問題原因總結：
目前生產環境所有資料庫的 Extract 程式已經按照 Oracle 的建議統一關閉 Bounded Recovery 功能，關閉該功能的後果是，每當 Extract 程式強制停止時，如果程式正在處理既未提交也未回滾的長時間執行事務（無論事務長短），則重啟 Extract 程式後，都必須進行 Normal Recovery，必須從這些既未提交也未回滾的事務中最早開始的事務在 Redo 或 Archived log 中的起點位置開始進行 Recovery。
如果未關閉Bounded Recovery，則 Extract 程式會對任何執行時間超過一個 BR 檢查點間隔（預設4小時）的事務每隔一個 BR 間隔執行一個檢查點，將事務相關的狀態和資料寫入 BR 檢查點檔案，這樣當 Extract 程式強行終止重啟後就會從上一個有效的 BR 檢查點或上個 BR 間隔內最早的既未提交也未回滾的事務的起點在日誌檔案中開始進行 Recovery，透過該功能可以保證 Extract 程式恢復的時間永遠不會超過 2 倍的 BR 間隔。
因此，導致本次問題的原因有：
1、GoldenGateExtract 的 Bounded Recovery 功能關閉，該功能官方的 Reference 推薦在未經Oracle Support 推薦情況下，不應對該功能做任何改動。
2、版本升級時在停止 Extract 程式時存在長事務，執行了 forcestop 操作
3、歸檔日誌被刪除
4、資料庫中存在不正常的長事務
5、資料運維不規範
三、解決方案：
1、重新初始化，能夠徹底解決問題，但是存在業務停機時間不可控風險。
2、恢復歸檔，能夠徹底解決問題，存在一定的同步延遲等待。
3、按照抽取時間點跳過該事務，可能存在丟失事務的風險，機率很低但卻是存在。
四、處理過程：
對於 XX2庫因找不到歸檔掛起的 Extract 程式，透過恢復歸檔日誌，重啟 Extract 程式，等待延遲解決。
對於 XX1庫因找不到歸檔掛起的 Extract 程式，經備份廠商核實不存在 Extract 程式執行恢復所需的歸檔的有效備份，無法恢復歸檔日誌，採取重置Extract 程式按照對 Extract 程式執行 forcestop 操作的時間點重新開始抽取，跳過該長事務。
Forcestop 時間點：
2013-04-1411:59:55 INFO    OGG-00987 Oracle GoldenGate Command Interpreter for Oracle: GGSCI command (oracle): send ESB_CX7forcestop.
2013-04-1411:59:56 INFO    OGG-01021 Oracle GoldenGate Capture for Oracle, esb_cx7.prm: Command received from GGSCI: FORCESTOP.
2013-04-1411:59:30 INFO    OGG-00987 Oracle GoldenGate Command Interpreter for Oracle: GGSCI command (oracle): send ESB_ZJ4forcestop.
2013-04-1411:59:30 INFO    OGG-01021 Oracle GoldenGate Capture for Oracle, esb_zj4.prm: Command received from GGSCI: FORCESTOP.
   重置時間點：
alter ESB_ZJ4 ,begin 2013-04-14 11:59:30
start ESB_ZJ4
alter ESB_CX7 ,begin 2013-04-14 11:59:56
start ESB_CX7
五、後續建議：
1、讓 Oracle 確認 Bounded Recovery 功能的合理性
2、規範歸檔日誌管理
3、規範資料運維
4、加強資料庫長事務監控和最佳化
5、規範資料庫版本升級流程，嚴格遵循 Oracle 推薦的 OGG 運維規範
本文乃作者原創，轉載請註明作者出處及原文連結，否則將追究法律責任：
作者：xiangsir
原文連結：http://blog.csdn.net/xiangsir/article/details/8806027

goldengate中長事務引起的問題

相關文章