oracle 长事务 逻辑日志,goldengate中长事务引起的问题
一、問題描述：
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
總結
以上是生活随笔為你收集整理的oracle 长事务 逻辑日志,goldengate中长事务引起的问题的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： bupt summer training
- 下一篇： Android 查看每个应用的最大可用内