1 業務系統申請加入OGG程式幾十張表，根據要求，將相關表新增到OGG抽取程式及投遞程式中，

第二天，發現OGG抽取程式延遲20多小時,進行相關原因分析。

EXTRACT RUNNING EXTTEST02 25:09:59 00:00:08

GGSCI (dbssvra) 5> info EXTTEST02

EXTRACT EXTTEST02 Last Started 2023-02-07 14:30 Status RUNNING

Checkpoint Lag 25:10:09 (updated 00:00:04 ago)

Log Read Checkpoint Oracle Redo Logs

2023-02-07 07:52:01 Thread 1, Seqno 679959, RBA 329074872

SCN 3722.502010847 (15986370286559)

Log Read Checkpoint Oracle Redo Logs

2023-02-07 07:52:01 Thread 2, Seqno 962867, RBA 1999074256

SCN 3722.502011018 (15986370286730)

2 OGG抽取程式延遲原因：CPU、記憶體、IO、引數設定不合理、長事務等

經過仔細分析，將CPU、記憶體、IO進行的排除，認為是正常的。那就剩下引數及長事務了。

3 進行引數排查：

執行如下命令，檢視OGG使用的記憶體資訊，根據如下資訊，認為OGG抽取程式的虛擬記憶體達到上限，

是導致OGG抽取程式執行緩慢。

GGSCI (dbssvra) 248> send extract EXTTEST02, CACHEMGR CACHESTATS

Sending CACHEMGR request to EXTRACT EXTTEST02 ...

CACHE OBJECT MANAGER statistics

CACHE MANAGER VM USAGE

vm current = 7.31G vm anon queues = 4.96G

vm anon in use = 2.36G vm file = 0

vm used max = 7.31G ==> CACHE BALANCED

檢視OGG抽取程式的引數，發現設定瞭如下記憶體引數，認為將記憶體設定的太小。

Oracle官方建議不要設定OGG抽取程式的記憶體引數，但由於發生多次由於抽取程式將記憶體耗盡，

導致主機伺服器hang的情況，此係統記憶體使用80%，故還不敢將ogg抽取程式的記憶體引數調整為預設值，只能進行調整。

TRANLOGOPTIONS DBLOGREADER, DBLOGREADERBUFSIZE 4194304

TRANLOGOPTIONS BUFSIZE 10000000

CACHEMGR CACHESIZE 1G

修改為：

--TRANLOGOPTIONS DBLOGREADER, DBLOGREADERBUFSIZE 4194304

--TRANLOGOPTIONS BUFSIZE 10000000

--CACHEMGR CACHESIZE 1G

TRANLOGOPTIONS DBLOGREADER

CACHEMGR CACHESIZE 16G

重啟OGG抽取程式，問題沒有解決。

4 檢視EXTTEST02程式的report,發現一直報長事務。

2023-02-08 10:43:54 WARNING OGG-01027 Long Running Transaction: XID 88.31.623522942, Items 0,

Extract EXTTEST02, Redo Thread 2, SCN 3722.332792647 (15986201068359), Redo Seq #962683,

Redo RBA 2900657168.

26556 records processed as of 2023-02-08 10:44:25 (rate 0,delta 0)

GGSCI (dbssvra) 87> send extract EXTTEST02,showtrans thread 2

Sending showtrans request to EXTRACT EXTTEST02 ...

Oldest redo log files necessary to restart Extract are:

Redo Thread 1, Redo Log Sequence Number 679959, SCN 3722.502130718 (15986370406430), RBA 459234320

Redo Thread 2, Redo Log Sequence Number 962683, SCN 3722.332792647 (15986201068359), RBA 2900657168

------------------------------------------------------------

XID: 88.31.623522942

I tems: 0 --經仔細檢視goldengate官方文件，此列為0，

即表示此事務不是goldengate抽取程式需要的，可以進行跳過。

懷疑是此事務導致OGG延遲增長，準備跳過此事務。

Extract: EXTTEST02

Redo Thread: 2

Start Time: 2023-02-07:01:42:16

SCN: 3722.332792647 (15986201068359)

Redo Seq: 962683

Redo RBA: 2900657168

Status: Running

SEND EXTRACT EXTTEST02, SKIPTRANS 88.31.623522942 THREAD 2

GGSCI (dbssvra) 2> SEND EXTRACT EXTTEST02, SKIPTRANS 88.31.623522942 THREAD 2

Sending SKIPTRANS request to EXTRACT EXTTEST02 ...

Are you sure you sure you want to skip transaction [XID 88.31.623522942, Redo Thread 2, Start Time 2023-02-07:01:42:16, SCN 3722.332792647 (15986201068359)]? (y/n)y

Sending SKIPTRANS request to EXTRACT EXTTEST02 ...

Transaction [XID 88.31.623522942, Redo Thread 2, Start Time 2023-02-07:01:42:16, SCN 3722.332792647 (15986201068359)] skipped.

OGG引數最佳化：將長事務告警資訊調整為告警及跳過空事務，此引數的調整，

可以讓OGG自動跳過空事務並釋放空事務相關的資源，且重啟後減少讀取歸檔日誌的數量，減少抽取程式恢復時間。

修改前

WARNLONGTRANS 2h,CHECKINTERVAL 10m

修改後

WARNLONGTRANS 2h,CHECKINTERVAL 10m,skipemptytrans

調整引數並重啟OGG程式，問題還是沒有解決，但已經往明朗的方向發展。

但每天OGG抽取程式卡主的時間點都在7:39分，連續觀察幾天後，認為是新增加的表導致的OGG抽取程式延遲，

但具體是哪個表，不清楚經過多次針對7:39分時間點的AWR，ASH等分析，還是不能確定是哪個表引起OGG抽取程式延遲。

5 針對OGG程式做trace，pstack,gstack等追蹤分析，沒有找到任何有用資訊。

只發現OGG的抽取程式延遲卡在都去歸檔日誌上，

申請goldengate官方的SR，認為是IO導致的，經仔細排查，經IO排除掉。

個人認為應該是遇見從業十幾年未遇見的問題，有可能是某一資源有限制（比如OGG抽取程式的VM，已經達到最大值），

導致的OGG抽取程式延遲。也有可能是業務系統幾分鐘對某個表執行了大量的操作，導致OGG將資源耗盡。

trace2相關的資訊

SUMMARY STATISTICS

General statistics:

0.00% Checking messages (includes checkpointing)

0.00% Checking periodic tasks

0.00% Waiting for more data

0.00% Converting ASCII header to internal

0.00% Converting ASCII data to internal

100.00% Reading input records

0.00% Writing output records (replicate_io)

0.00% Mapping columns

0.00% Outputting data records

0.00% Performing SQL statements

0.00% Performing BATCHSQL statements

0.00% Performing actual DB op

0.00% Preparing SQL statements

0.00% Performing transaction commits

0.00% Checkpointing

Redo log statistics:

0.00% Opening redo log file

0.00% Positioning into redo log file

0.00% Reading record from redo log file

0.01% Extracting subrecord from redo record

0.00% Extracting start subrecord

0.00% Extracting undo subrecord header

0.00% Extracting undo subrecord

0.00% Extracting redo subrecord header

0.00% Extracting undo subrecord

0.00% Extracting rollback subrecord

0.00% Extracting commit subrecord

0.00% Processing start subrecord

0.78% Processing data subrecord

0.00% Processing rollback subrecord

0.00% Processing commit subrecord

0.00% Retrieving and processing transaction items

0.00% Retrieving transaction item

0.00% Formatting output record

0.00% Formatting output record header

0.00% Validating update key data

0.00% Formatting output record data

0.00% Converting Oracle data to ASCII

0.00% Close redo log

6 大事務導致OGG抽取程式延遲

經過多次檢視執行send EXTTEST02 showtrans，總算發現了可疑的事務，但在資料庫進行檢視，

此事務已提交，不清楚此事務執行的相關SQL,無法確定是哪個表引起的。

2月7日

------------------------------------------------------------

X ID: 814.14.14101759 --事務ID

I tems: 22623282 --大事務，已經抽取了2千2百多萬條資料，事務還沒有結束。

Extract: EXTTEST02

Redo Thread: 2

Start Time: 2023-02-07:07:39:33

SCN: 3722.497851000 (15986366126712)

Redo Seq: 962860

Redo RBA: 157135376

Status: Running

2月16日

------------------------------------------------------------

XID: 579.25.9724995

Items: 8077902 --大事務，800多萬條資料，還沒有結束

Extract: EXTTEST02

Redo Thread: 1

Start Time: 2023-02-16:07:39:49

SCN: 3723.895718844 (15991058961852)

Redo Seq: 682982

Redo RBA: 1826037264

Status: Running

2月20日

------------------------------------------------------------

XID: 138.29.311639792

Items: 12612238 --大事務，已經抽取了1千2百多萬條資料，事務還沒有結束，只執行了幾分鐘。

Extract: EXTTEST02

Redo Thread: 2

Start Time: 2023-02-20:07:39:33

SCN: 3723.2254776926 (15992418019934)

Redo Seq: 972062

Redo RBA: 2890945040

Status: Running

7 由於事務已提交，無法確定事務執行的SQL，使用logminer對相關事務進行日誌挖掘，分析事務到底執行的SQL是什麼。

7.1 確定的事務ID為：138.29.311639792

XID: 138.29.311639792

Items: 8384843 --大事務

Extract: EXTTEST02

Redo Thread: 2

Start Time: 2023-02-20:07:39:33

SCN: 3723.2254776926 (15992418019934)

Redo Seq: 972062

Redo RBA: 2890945040

Status: Running

7.2 使用logminer對相關事務進行日誌挖掘，總算找到事務執行的相關SQL。

新增歸檔日誌到logminer中

BEGIN

dbms_logmnr.add_logfile(logfilename=>'+ARCH/DBNAME/ARCHIVELOG/2023_02_20

/thread_2_seq_972062.1774.1129275589',options=>dbms_logmnr.NEW);

END;

/

啟動日誌挖掘

EXECUTE DBMS_LOGMNR.START_LOGMNR(OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG);

檢視事務ID（138.29.311639792）檢視執行的SQL

SELECT SESSION#,SERIAL#,sql_redo,XID,XIDUSN,XIDSLT,XIDSQN

FROM v$logmnr_contents where XIDUSN='138' and XIDSLT='29' and XIDSQN='311639792';

SESSION# SERIAL# sql_redo, XID, XIDUSN, XIDSLT, XIDSQN

-------- ------- ------------------------------------------------------------------------ ------- ---------- --------- --------

5378 9303 update "USER_1"."TABLE_A" set "WRITE_TIME" = TO_ 8A001D00F03E9312 138 29 311639792

.............

結束日誌挖掘

EXECUTE dbms_logmnr.END_LOGMNR;

使用歷史會話再一次對驗證業務系統執行了哪些SQL

INSTANCE_NUMBER TIME_SA SESSION_ID SESSION_SERIAL# SQL_ID WAIT_CLASS BLOCKING_SESSION BLOCKING_SESSION_SERIAL#

--------------- ------------------------------ ---------- --------------- -------------------- -------------------- ---------------- ------------------------

2 2023-02-20 07:30:12 5378 9303 5zj438nbjpsnc

2 2023-02-20 07:30:22 5378 9303 5zj438nbjpsnc

.......

2 2023-02-20 07:31:43 5378 9303 2pgrah1dz9rp1

.......

2 2023-02-20 07:33:44 5378 9303 ah4skxaa4wjpg

......

2 2023-02-20 07:36:05 5378 9303 24jssqmxrg58t

....

2 2023-02-20 07:37:36 5378 9303 dkaxpn8u8s3xn

....

2 2023-02-20 07:39:27 5378 9303 f142qzj7r76yr

....

2 2023-02-20 07:53:25 5378 9303 4bbagth0j22dn Cluster

2 2023-02-20 07:53:35 5378 9303 gaqru9wr6b1kv

....

2 2023-02-20 07:56:27 5378 9303 d5nnqs90fm7rr

....

2 2023-02-20 08:03:00 5378 9303 4kpvuf1zysy7n

2 2023-02-20 08:03:11 5378 9303 4v06s9w1mu8g8

2 2023-02-20 08:03:21 5378 9303 4v06s9w1mu8g8

2 2023-02-20 08:03:31 5378 9303 4v06s9w1mu8g8

2 2023-02-20 08:03:41 5378 9303 4v06s9w1mu8g8

200 rows selected.

和2023-02-20:07:39:33 時間點最近的為f142qzj7r76yr SQL , 此SQL執行計劃為全表掃描

檢視SQL執行的時間及耗費的資源

set linesize 200

set pagesize 999

col OWNER for a20

col SEGMENT_NAME for a40

col SEGMENT_TYPE for a20

select OWNER,SEGMENT_NAME,SEGMENT_TYPE,trunc(sum(BYTES)/1024/1024/1024) from dba_segments where owner='USER_1' and

SEGMENT_NAME in ('TABLE_A')

group by OWNER,SEGMENT_NAME,SEGMENT_TYPE

order by SEGMENT_TYPE,trunc(sum(BYTES)/1024/1024/1024) ;

檢視錶的大小，此表大小為750G，走全表掃描，很有可能會導致將OGG抽取程式的資源耗盡

OWNER SEGMENT_NAME SEGMENT_TYPE TRUNC(SUM(BYTES)/1024/1024/1024)

-------------------- ---------------------------------------- -------------------- --------------------------------

USER_1 TABLE_A TABLE PARTITION 750

檢視此表每日新增的資料量，在1800萬左右。

SYS@DBNAME1 >select count(1) from "USER_1"."TABLE_A" partition(TABLE_A20221216);

COUNT(1)

----------

18179182

在AWR中只有一行,由於此行排在最後，故剛開始時就將其忽略掉,如下

Buffer Gets Executions Gets per Exec %Total Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text

58,785,636 1 58,785,636.00 1.32 835.74 85 3.8 f142qzj7r76yr MERGE INTO TABLE_A CRF

根據buffer gets中資料塊的數量，計算耗費的記憶體，每個資料塊的大小為8K,計算後發現一條SQL耗費的記憶體為459G，

故導致OGG抽取程式執行緩慢：

SYS@DBNAME1 >select (58785636*8)/1024 from dual;

(58785636*8)/1024

-----------------

459262.781

解決方法：

業務系統最佳化相關業務邏輯及SQL，OGG抽取程式延時問題解決。

問題總結：

此次故障解決，耗時特長，用時12天，才找到真正原因，其中將CPU、記憶體、IO、AWR、ASH、長事務、引數等都

排查過，並進行了排除後，最終才確定是由於在很短的時間內，資料庫執行了一個大事務，邏輯讀459G，將OGG抽取程式的

資源耗盡，導致OGG抽取程式執行特別緩慢。此事件是運維十幾年來第一次因為大事務導致的抽取程式延遲，還是有一定借鑑

意義的。

大事務導致的OGG抽取程式每天7：39定時延時，執行極其緩慢

相關文章