大事务导致的OGG抽取进程每天7：39定时延时，运行极其缓慢

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