OGG Replicat延迟-由于在无主键表删除大批量数据导致

本文转自：http://blog.sina.com.cn/s/blog_4d22b9720102v3xo.html

感谢原作者

OGG Replicat延迟-由于在无主键表删除大批量数据导致

最近发现IPS3.0上海容灾库GGS Replicat进程每天08：00开始延迟：

oracle@DBha01$./ggsci   OracleGoldenGate Command Interpreter for Oracle Version11.2.1.0.1 OGGCORE_11.2.1.0.1_PLATFORMS_120423.0230_FBO Solaris,sparc, 64bit (optimized), Oracle 10g on Apr 24 201209:06:57   Copyright(C) 1995, 2012, Oracle and/or its affiliates. All rightsreserved.       GGSCI(DBha01) 1> info all   Program    Status     Group      Lag at Chkpt  Time Since Chkpt   MANAGER    RUNNING                                           EXTRACT    RUNNING    DPE7C      00:00:00     00:00:04    EXTRACT    RUNNING    DPELC      00:00:00     00:00:05    EXTRACT    RUNNING    DPEPC      00:00:00     00:00:01    EXTRACT    RUNNING    EXT7C      00:00:00     00:00:01    EXTRACT    RUNNING    EXTLC      00:00:00     00:00:02    EXTRACT    RUNNING    EXTPC      00:00:00     00:00:06    REPLICAT    RUNNING    REP7C      00:00:00     00:00:08    REPLICAT    RUNNING    REPLC      00:00:00     02:12:03     REPLICAT    RUNNING    REPPC      00:00:00     00:00:05

 

大约2个小时后，处于正常状态。

通过GGS trace/trace2命令（如下）：

send extract extlc trace2 /ggs/dirtmp/trace2.log send extract extlc trace /ggs/dirtmp/trace.log  send  extract extlc trace2 of send extract extlc trace off

发现当时GGS正在处理的SQL语句如下：

DELETE FROM"IPS2"."ETL_TRAD_BANK"  WHERE "TRAN_DATE" = :b0AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND "MER_ACC_CODE" = :b3 AND"TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND "CCY_CODE" = :b6 AND"TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND "SUPPLIER_BILL_NO" =:b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" = :b11 AND"REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND "FINISH_DATE" =:b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND "BANK_COST" isNULL AND "REFUND_BANK_COST" is NULL AND "ORI_TRAN_NO" is NULL AND"STATUS" = :b20 AND ROWNUM = 1     09:57:38.223 (539896) preparing new dynamicstmt                      DELETE FROM "IPS2"."ETL_TRAD_BANK"  WHERE"TRAN_DATE" = :b0 AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND"MER_ACC_CODE" = :b3 AND "TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND"CCY_CODE" = :b6 AND "TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND"SUPPLIER_BILL_NO" = :b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" =:b11 AND "REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND"FINISH_DATE" = :b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND"BANK_COST" is NULL AND "REFUND_BANK_COST" is NULL AND"ORI_TRAN_NO" is NULL AND "STATUS" = :b20 AND ROWNUM = 1 09:57:38.223 (539896) iotype:3 mode:0 09:57:38.223 (539896) BIND val for col:0 :32 30len:19 blen:0 09:57:38.223 (539896) BIND val for col:1 :4e 54len:17 blen:0 09:57:38.223 (539896) BIND val for col:2 :31 32len:4 blen:0 09:57:38.223 (539896) BIND val for col:3 :30 32len:6 blen:0 09:57:38.223 (539896) BIND val for col:4 :4e 54len:2 blen:0 09:57:38.223 (539896) BIND val for col:5 :31 0len:1 blen:0 09:57:38.223 (539896) BIND val for col:6 :52 4dlen:3 blen:0 09:57:38.223 (539896) BIND val for col:7 :32 30len:3 blen:0 09:57:38.223 (539896) BIND val for col:8 :31 31len:4 blen:0 09:57:38.223 (539896) BIND val for col:9 :31 31len:12 blen:0 09:57:38.223 (539896) BIND val for col:10 :31 31len:16 blen:0 09:57:38.223 (539896) BIND val for col:11 :6e 75len:4 blen:0 09:57:38.223 (539896) BIND val for col:13 :6e 75len:4 blen:0 09:57:38.223 (539896) BIND val for col:14 :32 30len:19 blen:0 09:57:38.223 (539896) BIND val for col:15 :31 0len:1 blen:0 09:57:38.223 (539896) BIND val for col:16 :32 0len:1 blen:0 09:57:38.223 (539896) BIND val for col:20 :31 0len:1 blen:0 09:57:38.333 (540006) OCI statement executedsuccessfully... 09:57:38.333 (540006) executed stmt(sql_err=0) 09:57:38.333 (540006) exitedperform_sql_statements (sql_err=0,recs output=5198) 09:57:38.333 (540006) * --- enteringREAD_EXTRACT_RECORD --- * 09:57:38.333 (540006) exited READ_EXTRACT_RECORD(stat=0, seqno=1248, rba=3972388) 09:57:38.333 (540006) processing record forIPS2.ETL_TRAD_BANK 09:57:38.333 (540006) mapping record 09:57:38.333 (540006) enteringperform_sql_statements (normal) 09:57:38.333 (540006) entering execute_statement(op_type=3,IPS2.ETL_TRAD_BANK) 09:57:38.333 (540006) CDR iotype:3  mode:0 09:57:38.333 (540006) preparing new dynamicstmt                      DELETE FROM "IPS2"."ETL_TRAD_BANK"  WHERE"TRAN_DATE" = :b0 AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND"MER_ACC_CODE" = :b3 AND "TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND"CCY_CODE" = :b6 AND "TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND"SUPPLIER_BILL_NO" = :b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" =:b11 AND "REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND"FINISH_DATE" = :b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND"BANK_COST" is NULL AND "REFUND_BANK_COST" is NULL AND"ORI_TRAN_NO" is NULL AND "STATUS" = :b20 AND ROWNUM = 1 09:57:38.333 (540006) iotype:3 mode:0 09:57:38.333 (540006) BIND val for col:0 :32 30len:19 blen:0 09:57:38.333 (540006) BIND val for col:1 :4e 54len:17 blen:0 09:57:38.333 (540006) BIND val for col:2 :31 32len:4 blen:0 09:57:38.333 (540006) BIND val for col:3 :30 31len:6 blen:0 09:57:38.333 (540006) BIND val for col:4 :4e 54len:2 blen:0 09:57:38.333 (540006) BIND val for col:5 :31 0len:1 blen:0 09:57:38.333 (540006) BIND val for col:6 :52 4dlen:3 blen:0 09:57:38.333 (540006) BIND val for col:7 :34 30len:3 blen:0 09:57:38.333 (540006) BIND val for col:8 :31 31len:4 blen:0 09:57:38.333 (540006) BIND val for col:9 :33 30len:12 blen:0 09:57:38.333 (540006) BIND val for col:10 :31 31len:16 blen:0 09:57:38.333 (540006) BIND val for col:11 :6e 75len:4 blen:0 09:57:38.333 (540006) BIND val for col:13 :6e 75len:4 blen:0 09:57:38.333 (540006) BIND val for col:14 :32 30len:19 blen:0 09:57:38.333 (540006) BIND val for col:15 :30 0len:1 blen:0 09:57:38.333 (540006) BIND val for col:16 :32 0len:1 blen:0 09:57:38.333 (540006) BIND val for col:20 :31 0len:1 blen:0 09:57:38.433 (540106) OCI statement executedsuccessfully... 09:57:38.433 (540106) executed stmt(sql_err=0) 09:57:38.433 (540106) exitedperform_sql_statements (sql_err=0,recs output=5199) 09:57:38.433 (540106) * --- enteringREAD_EXTRACT_RECORD --- * 09:57:38.433 (540106) exited READ_EXTRACT_RECORD(stat=0, seqno=1248, rba=3972760) 09:57:38.433 (540106) processing record forIPS2.ETL_TRAD_BANK 09:57:38.433 (540106) mapping record 09:57:38.433 (540106) enteringperform_sql_statements (normal) 09:57:38.433 (540106) entering execute_statement(op_type=3,IPS2.ETL_TRAD_BANK) 09:57:38.433 (540106) CDR iotype:3  mode:0 09:57:38.433 (540106) preparing new dynamicstmt                      DELETE FROM "IPS2"."ETL_TRAD_BANK"  WHERE"TRAN_DATE" = :b0 AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND"MER_ACC_CODE" = :b3 AND "TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND"CCY_CODE" = :b6 AND "TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND"SUPPLIER_BILL_NO" = :b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" =:b11 AND "REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND"FINISH_DATE" = :b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND"BANK_COST" is NULL AND "REFUND_BANK_COST" is NULL AND"ORI_TRAN_NO" is NULL AND "STATUS" = :b20 AND ROWNUM = 1 09:57:38.433 (540106) iotype:3 mode:0 09:57:38.433 (540106) BIND val for col:0 :32 30len:19 blen:0 09:57:38.433 (540106) BIND val for col:1 :4e 54len:17 blen:0 09:57:38.433 (540106) BIND val for col:2 :31 32len:4 blen:0 09:57:38.433 (540106) BIND val for col:3 :30 32len:6 blen:0 09:57:38.433 (540106) BIND val for col:4 :4e 54len:2 blen:0 09:57:38.433 (540106) BIND val for col:5 :31 0len:1 blen:0 09:57:38.433 (540106) BIND val for col:6 :52 4dlen:3 blen:0 09:57:38.433 (540106) BIND val for col:7 :31 30len:3 blen:0 09:57:38.433 (540106) BIND val for col:8 :31 31len:4 blen:0 09:57:38.433 (540106) BIND val for col:9 :31 31len:12 blen:0 09:57:38.433 (540106) BIND val for col:10 :31 31len:16 blen:0 09:57:38.433 (540106) BIND val for col:11 :6e 75len:4 blen:0 09:57:38.433 (540106) BIND val for col:13 :6e 75len:4 blen:0 09:57:38.433 (540106) BIND val for col:14 :32 30len:19 blen:0 09:57:38.433 (540106) BIND val for col:15 :31 0len:1 blen:0 09:57:38.433 (540106) BIND val for col:16 :32 0len:1 blen:0 09:57:38.433 (540106) BIND val for col:20 :31 0len:1 blen:0 09:57:38.543 (540216) OCI statement executedsuccessfully... 09:57:38.543 (540216) executed stmt(sql_err=0) 09:57:38.543 (540216) exitedperform_sql_statements (sql_err=0,recs output=5200) 09:57:38.543 (540216) * --- enteringREAD_EXTRACT_RECORD --- * 09:57:38.543 (540216) exited READ_EXTRACT_RECORD(stat=0, seqno=1248, rba=3973132) 09:57:38.543 (540216) processing record forIPS2.ETL_TRAD_BANK 09:57:38.543 (540216) mapping record 09:57:38.543 (540216) enteringperform_sql_statements (normal) 09:57:38.543 (540216) entering execute_statement(op_type=3,IPS2.ETL_TRAD_BANK) 09:57:38.543 (540216) CDR iotype:3  mode:0 09:57:38.543 (540216) preparing new dynamicstmt                      DELETE FROM "IPS2"."ETL_TRAD_BANK"  WHERE"TRAN_DATE" = :b0 AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND"MER_ACC_CODE" = :b3 AND "TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND"CCY_CODE" = :b6 AND "TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND"SUPPLIER_BILL_NO" = :b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" =:b11 AND "REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND"FINISH_DATE" = :b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND"BANK_COST" is NULL AND "REFUND_BANK_COST" is NULL AND"ORI_TRAN_NO" is NULL AND "STATUS" = :b20 AND ROWNUM = 1 09:57:38.543 (540216) iotype:3 mode:0 09:57:38.543 (540216) BIND val for col:0 :32 30len:19 blen:0 09:57:38.543 (540216) BIND val for col:1 :4e 54len:17 blen:0 09:57:38.543 (540216) BIND val for col:2 :31 32len:4 blen:0 09:57:38.543 (540216) BIND val for col:3 :30 32len:6 blen:0 09:57:38.543 (540216) BIND val for col:4 :4e 54len:2 blen:0 09:57:38.543 (540216) BIND val for col:5 :31 0len:1 blen:0 09:57:38.543 (540216) BIND val for col:6 :52 4dlen:3 blen:0 09:57:38.543 (540216) BIND val for col:7 :35 30len:3 blen:0 09:57:38.543 (540216) BIND val for col:8 :31 31len:4 blen:0 09:57:38.543 (540216) BIND val for col:9 :31 31len:12 blen:0 09:57:38.543 (540216) BIND val for col:10 :31 31len:16 blen:0 09:57:38.543 (540216) BIND val for col:11 :6e 75len:4 blen:0 09:57:38.543 (540216) BIND val for col:13 :6e 75len:4 blen:0 09:57:38.543 (540216) BIND val for col:14 :32 30len:19 blen:0 09:57:38.543 (540216) BIND val for col:15 :33 0len:1 blen:0 09:57:38.543 (540216) BIND val for col:16 :32 0len:1 blen:0 09:57:38.543 (540216) BIND val for col:20 :31 0len:1 blen:0 09:57:38.643 (540316) OCI statement executedsuccessfully... 09:57:38.643 (540316) executed stmt(sql_err=0) 09:57:38.643 (540316) exitedperform_sql_statements (sql_err=0,recs output=5201) 09:57:38.643 (540316) * --- enteringREAD_EXTRACT_RECORD --- * 09:57:38.643 (540316) exited READ_EXTRACT_RECORD(stat=0, seqno=1248, rba=3973504) 09:57:38.643 (540316) processing record forIPS2.ETL_TRAD_BANK 09:57:38.643 (540316) mapping record 09:57:38.643 (540316) enteringperform_sql_statements (normal) 09:57:38.643 (540316) entering execute_statement(op_type=3,IPS2.ETL_TRAD_BANK) 09:57:38.643 (540316) CDR iotype:3  mode:0 09:57:38.653 (540326) preparing new dynamicstmt                      DELETE FROM "IPS2"."ETL_TRAD_BANK"  WHERE"TRAN_DATE" = :b0 AND "TRAN_NO" = :b1 AND "SYS_ID" = :b2 AND"MER_ACC_CODE" = :b3 AND "TRAN_TYPE" = :b4 AND "TRAN_TP" = :b5 AND"CCY_CODE" = :b6 AND "TRAN_AMOUNT" = :b7 AND "BANK_CODE" = :b8 AND"SUPPLIER_BILL_NO" = :b9 AND "CHANNEL_CODE" = :b10 AND "AUTH_NO" =:b11 AND "REFRENCE_NO" is NULL AND "BANK_ACC_NO" = :b13 AND"FINISH_DATE" = :b14 AND "FEE_AMT" = :b15 AND "FEE_FLAG" = :b16 AND"BANK_COST" is NULL AND "REFUND_BANK_COST" is NULL AND"ORI_TRAN_NO" is NULL AND "STATUS" = :b20 AND ROWNUM = 1 09:57:38.653 (540326) iotype:3 mode:0 09:57:38.653 (540326) BIND val for col:0 :32 30len:19 blen:0 09:57:38.653 (540326) BIND val for col:1 :4e 54len:17 blen:0 09:57:38.653 (540326) BIND val for col:2 :31 32len:4 blen:0 09:57:38.653 (540326) BIND val for col:3 :30 32len:6 blen:0 09:57:38.653 (540326) BIND val for col:4 :4e 54len:2 blen:0 09:57:38.653 (540326) BIND val for col:5 :31 0len:1 blen:0 09:57:38.653 (540326) BIND val for col:6 :52 4dlen:3 blen:0 09:57:38.653 (540326) BIND val for col:7 :32 39len:4 blen:0 09:57:38.653 (540326) BIND val for col:8 :31 31len:4 blen:0 09:57:38.653 (540326) BIND val for col:9 :31 31len:12 blen:0 09:57:38.653 (540326) BIND val for col:10 :31 31len:16 blen:0 09:57:38.653 (540326) BIND val for col:11 :6e 75len:4 blen:0 09:57:38.653 (540326) BIND val for col:13 :6e 75len:4 blen:0 09:57:38.653 (540326) BIND val for col:14 :32 30len:19 blen:0 09:57:38.653 (540326) BIND val for col:15 :31 35len:2 blen:0 09:57:38.653 (540326) BIND val for col:16 :32 0len:1 blen:0 09:57:38.653 (540326) BIND val for col:20 :31 0len:1 blen:0 09:57:38.753 (540426) OCI statement executedsuccessfully... 09:57:38.753 (540426) executed stmt(sql_err=0) 09:57:38.753 (540426) exitedperform_sql_statements (sql_err=0,recs output=5202)

 

 

联系到程序开发人员，其实生产应用中的SQL如下：

由以上可知，GGS将以上SQL1 DeleteSQL语句在目标端执行时，自动分拆一笔一笔的删除执行，进一步了解程序知晓每天删除20w笔记录，所以才导致Replicat进程Lag时间过长。。删除大批量的数据本来就不是好的程序设计方式，但是先不顾此，在此不讨论，继续分析Replicat  TimeLag问题。从网络查询了一些类似解决方法，比如建立主键以及对表进行优化信息统计。

 

在这个程序之前，还有另外一支程序也是每天删除大约20w笔记录，但是并没有导致GGS Replicat进程出现延迟现象。于是，针对这两支程序进行对比，主要看看SQL有哪些差异，TABLE有哪些差异。分析的结果就是，这支程序删除20w记录的表没有主键，那支程序涉及到表有主键。

 

后来给出的初步的解决方案如下：
1）.增加GROUPTRANSOPS 和 MAXTRANSOPS；

并没有达到期望的效果。
2）.增加主键；

问题解决。
3）.程序修改不删除数据，改建分区表。

实际上，2/3是同时进行的，只是3中没有停止删除数据而已，观察一天问题得以解决。

 

因此，看来对于删除大量数据表，使用GGS作为容灾时，需要在被删除表上建立主键（尽管GGS一致声称没有主键也可以，将所有列合起来当成唯一约束或者主键）。