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抽取进程运行特别缓慢。此事件是运维十几年来第一次因为大事务导致的抽取进程延迟，还是有一定借鉴
意义的。