解决goldengate复制进程应用缓慢一例

前段时间配置的oracle10g-->11g的gg，到目前为止应用都还正常，没什么问题，今天测试了下大批量更新的应用情况,具体操作如下：

源库：

create table m_order_test5 as select * from m_order_info where 1=2;

insert into m_order_test5 select * from m_order_info;

commit;

m_order_info 表主键、约束都有，新建的表m_order_test5没有任何主键和约束，实验到此，主库和目标库同步都没什么问题，然后就是大批量的更新操作：

update m_order_test5 set link_name='mordertest5';

commit;

之后到目标观察发现一直没有应用过去，相关日志如下：

源库err.log内容：

2012-04-11 13:34:42 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001878.

2012-04-11 13:34:43 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001879.

2012-04-11 13:34:44 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001880.

2012-04-11 13:34:46 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001881.

2012-04-11 13:34:47 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001882.

2012-04-11 13:34:48 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001883.

2012-04-11 13:34:49 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001884.

2012-04-11 13:34:51 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001885.

2012-04-11 13:34:52 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001886.

2012-04-11 13:34:53 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001887.

2012-04-11 13:34:55 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001888.

2012-04-11 13:34:56 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001889.

2012-04-11 13:34:57 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001890.

2012-04-11 13:34:59 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001891.

2012-04-11 13:35:00 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001892.

2012-04-11 13:35:01 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001893.

2012-04-11 13:35:02 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001894.

2012-04-11 13:35:04 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001895.

2012-04-11 13:35:05 INFO OGG-01026 Oracle GoldenGate Capture for Oracle, dpump.prm: Rolling over remote file /home/oracle/ggs/dirdat/k1001896.

目标库err.log内容：

2012-04-11 13:39:21 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001890 to disk.

2012-04-11 13:39:21 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001890.

2012-04-11 13:39:21 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001891 (byte -1, current EOF 0).

2012-04-11 13:39:23 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001891 to disk.

2012-04-11 13:39:23 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001891 to disk.

2012-04-11 13:39:23 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001891.

2012-04-11 13:39:23 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001892 (byte -1, current EOF 0).

2012-04-11 13:39:24 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001892 to disk.

2012-04-11 13:39:24 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001892 to disk.

2012-04-11 13:39:24 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001892.

2012-04-11 13:39:24 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001893 (byte -1, current EOF 0).

2012-04-11 13:39:25 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001893 to disk.

2012-04-11 13:39:25 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001893 to disk.

2012-04-11 13:39:25 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001893.

2012-04-11 13:39:25 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001894 (byte -1, current EOF 0).

2012-04-11 13:39:27 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001894 to disk.

2012-04-11 13:39:27 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001894 to disk.

2012-04-11 13:39:27 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001894.

2012-04-11 13:39:27 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001895 (byte -1, current EOF 0).

2012-04-11 13:39:28 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001895 to disk.

2012-04-11 13:39:28 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001895 to disk.

2012-04-11 13:39:28 INFO OGG-01670 Oracle GoldenGate Collector for Oracle: Closing /home/oracle/ggs/dirdat/k1001895.

2012-04-11 13:39:28 INFO OGG-01669 Oracle GoldenGate Collector for Oracle: Opening /home/oracle/ggs/dirdat/k1001896 (byte -1, current EOF 0).

2012-04-11 13:45:02 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001896 to disk.

2012-04-11 13:45:02 INFO OGG-01735 Oracle GoldenGate Collector for Oracle: Synchronizing /home/oracle/ggs/dirdat/k1001896 to disk.

之后就一直卡在这里，后续的dml操作（包括其他表）都应用不了，然后到目标库查询相关sql语句发现，之前的update操作变成了下面的格式：

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "MYNET_APP"."M_ORDER_TEST5"

SET "ORDER_ID" = :a114,

"MEMBER_ID" = :a115,

"ORDER_SOURCE" = :a116,

"ORDER_TYPE" = :a117,

"SUBMIT_USER_ID" = :a118,

"LINK_NAME" = :a119,

"SEX" = :a120,

"EMAIL" = :a121,

"POSTCODE" = :a122,

"PHONE" = :a123,

"MOBILE" = :a124,

"COUNTRY" = :a125,

"CITY" = :a126,

"DISTRICT" = :a127,

"ADDRESS" = :a128,

"AREA_CODE" = :a129,

"AREA_ID" = :a130,

"PROCESS_CODE" = :a131,

"SEND_REQUIRE" = :a132,

"SEND_TYPE" = :a133,

"GOODS_AMOUNT" = :a134,

"AMOUNT" = :a135,

"POST_FEE" = :a136,

"SEND_PERIOD" = :a137,

"CREATED_DATE" = :a138,

"PAY_AMOUNT" = :a139,

"RECEIVE_AMOUNT" = :a140,

"POINT_FLAG" = :a141,

"POINT_AMOUNT" = :a142,

"PAY_ACCOUNT_AMOUNT" = :a143,

"PAY_TYPE" = :a144,

"PAY_DATE" = :a145,

"PAY_MEMBER_ID" = :a146,

"INVOICE_NEED_FLAG" = :a147,

"SEND_USER_ID" = :a148,

"APPOINT_SEND_DATE" = :a149,

"SEND_DATE" = :a150,

"INTRO_MEMBER_ID" = :a151,

"COMFIRM_PAY_DATE" = :a152,

"COMFIRM_PLAY_USER_ID" = :a153,

"CANCEL_DATE" = :a154,

"CANCEL_USER_ID" = :a155,

"EXPRESS_FLAG" = :a156,

"SUBMIT_DATE" = :a157,

"COMFIRM_USER_ID" = :a158,

"COMFIRM_DATE" = :a159,

"UPDATE_FLAG" = :a160,

"UPDATE_DATE" = :a161,

"GOODS_STATUS" = :a162,

"AMOUNT_STATUS" = :a163,

"ORDER_STATUS" = :a164,

"GET_POINT" = :a165,

"GET_COMMENT_POINT" = :a166,

"ADDRESS_ID" = :a167,

"IP" = :a168,

"VERSION" = :a169,

"CONNECT_USER_ID" = :a170,

"CONNECT_ID" = :a171,

"CONNECT_DATE" = :a172,

"HOUSE_ID" = :a173,

"DISTRIBUTE_DATE" = :a174,

"DISTRIBUTE_USER_ID" = :a175,

"VIP_FLAG" = :a176,

"STOCK_OUT_FLAG" = :a177,

"GOODS_LINE" = :a178,

"FIRST_EXPERIENCE_FLAG" = :a179,

"EXTERNAL_USERID" = :a180,

"REDUCTION_BY_POINTS" = :a181,

"NEED_CONFIRM_SEND" = :a182,

"COUPON_REDUCTION_AMOUNT" = :a183,

"PFLAG" = :a184,

"COME_ACTIVITY" = :a185,

"EXTERNAL_USER_ID" = :a186,

"IS_GET_SCORE" = :a187,

"ORDER_SOURCE_TYPE" = :a188,

"PAY_REMIND_COUNT" = :a189,

"RESULT_FLAG" = :a190,

"PROMOTION_REDUCTION_MONEY" = :a191,

"PORMOTION_EXTRA_MONEY" = :a192,

"POINTS_REDUCTION_MONEY" = :a193,

"SUBMIT_AGENT_NO" = :a194,

"CALL_SESSION_ID" = :a195,

"MAKE_ORDER_TYPE" = :a196,

"PROVINCE" = :a197,

"SEND_DATE_TYPE" = :a198,

"AUTUMN_COUPON_CODE" = :a199,

"NET_ORDER_SOURCE" = :a200,

"NET_ORDER_SOURCE_DETAIL" = :a201,

"LEVEL_DISCOUNT" = :a202,

"PURCHASE_ID" = :a203,

"IS_FREETEA" = :a204,

"GET_SOURCE" = :a205,

"REG_SOURCE_ID" = :a206,

"AFFILIATE_ID" = :a207,

"SITE_LOG_PARA" = :a208,

"SITE_USER_LOG_PARA" = :a209,

"YM_COUPON_REDU_MONEY" = :a210,

"F_HOUSE_ID" = :a211,

"PRE_PAY_MONEY" = :a212,

"CONNECT_TYPE" = :a213,

"ORDER_LEVEL" = :a214,

"EXPRESS_COST" = :a215,

"PACKAGING_MOUTH" = :a216,

"FIRST_CONFIRM_DATE" = :a217,

"PRE_PAY_FLAG" = :a218,

"TIMES" = :a219,

"SETTLED_FLAG" = :a220,

"PAY_MOBILE" = :a221,

"REQUIRE_SEND_DATE" = :a222,

"CARD_AMOUNT" = :a223,

"LINKED_ORDER_ID" = :a224,

"INVOICE_DETAIL_NEED_FLAG" = :a225,

"EXPORT_FLAG" = :a226,

"ORIGINAL_HOUSE_ID" = :a227

WHERE "ORDER_ID" = :b0

AND "MEMBER_ID" = :b1

AND "ORDER_SOURCE" = :b2

AND "ORDER_TYPE" = :b3

AND "SUBMIT_USER_ID" = :b4

AND "LINK_NAME" = :b5

AND "SEX" is NULL

AND "EMAIL" = :b7

AND "POSTCODE" = :b8

AND "PHONE" is NULL

AND "MOBILE" = :b10

AND "COUNTRY" is NULL

AND "CITY" is NULL

AND "DISTRICT" is NULL

AND "ADDRESS" = :b14

AND "AREA_CODE" is NULL

AND "AREA_ID" = :b16

AND "PROCESS_CODE" is NULL

AND "SEND_REQUIRE" = :b18

AND "SEND_TYPE" = :b19

AND "GOODS_AMOUNT" = :b20

AND "AMOUNT" = :b21

AND "POST_FEE" = :b22

AND "SEND_PERIOD" = :b23

AND "CREATED_DATE" = :b24

AND "PAY_AMOUNT" = :b25

AND "RECEIVE_AMOUNT" = :b26

AND "POINT_FLAG" = :b27

AND "POINT_AMOUNT" = :b28

AND "PAY_ACCOUNT_AMOUNT" = :b29

AND "PAY_TYPE" = :b30

AND "PAY_DATE" = :b31

AND "PAY_MEMBER_ID" is NULL

AND "INVOICE_NEED_FLAG" = :b33

AND "SEND_USER_ID" = :b34

AND "APPOINT_SEND_DATE" = :b35

AND "SEND_DATE" = :b36

AND "INTRO_MEMBER_ID" is NULL

AND "COMFIRM_PAY_DATE" = :b38

AND "COMFIRM_PLAY_USER_ID" = :b39

AND "CANCEL_DATE" is NULL

AND "CANCEL_USER_ID" is NULL

AND "EXPRESS_FLAG" = :b42

AND "SUBMIT_DATE" = :b43

AND "COMFIRM_USER_ID" is NULL

AND "COMFIRM_DATE" = :b45

AND "UPDATE_FLAG" = :b46

AND "UPDATE_DATE" is NULL

AND "GOODS_STATUS" is NULL

AND "AMOUNT_STATUS" is NULL

AND "ORDER_STATUS" = :b50

AND "GET_POINT" = :b51

AND "GET_COMMENT_POINT" = :b52

AND "ADDRESS_ID" = :b53

AND "IP" is NULL

AND "VERSION" = :b55

AND "CONNECT_USER_ID" = :b56

AND "CONNECT_ID" = :b57

AND "CONNECT_DATE" = :b58

AND "HOUSE_ID" = :b59

AND "DISTRIBUTE_DATE" is NULL

AND "DISTRIBUTE_USER_ID" is NULL

AND "VIP_FLAG" = :b62

AND "STOCK_OUT_FLAG" = :b63

AND "GOODS_LINE" = :b64

AND "FIRST_EXPERIENCE_FLAG" = :b65

AND "EXTERNAL_USERID" is NULL

AND "REDUCTION_BY_POINTS" = :b67

AND "NEED_CONFIRM_SEND" is NULL

AND "COUPON_REDUCTION_AMOUNT" = :b69

AND "PFLAG" is NULL

AND "COME_ACTIVITY" is NULL

AND "EXTERNAL_USER_ID" is NULL

AND "IS_GET_SCORE" is NULL

AND "ORDER_SOURCE_TYPE" is NULL

AND "PAY_REMIND_COUNT" is NULL

AND "RESULT_FLAG" = :b76

AND "PROMOTION_REDUCTION_MONEY" = :b77

AND "PORMOTION_EXTRA_MONEY" = :b78

AND "POINTS_REDUCTION_MONEY" = :b79

AND "SUBMIT_AGENT_NO" = :b80

AND "CALL_SESSION_ID" = :b81

AND "MAKE_ORDER_TYPE" = :b82

AND "PROVINCE" is NULL

AND "SEND_DATE_TYPE" = :b84

AND "AUTUMN_COUPON_CODE" is NULL

AND "NET_ORDER_SOURCE" = :b86

AND "NET_ORDER_SOURCE_DETAIL" is NULL

AND "LEVEL_DISCOUNT" = :b88

AND "PURCHASE_ID" is NULL

AND "IS_FREETEA" is NULL

AND "GET_SOURCE" is NULL

AND "REG_SOURCE_ID" is NULL

AND "AFFILIATE_ID" is NULL

AND "SITE_LOG_PARA" is NULL

AND "SITE_USER_LOG_PARA" is NULL

AND "YM_COUPON_REDU_MONEY" is NULL

AND "F_HOUSE_ID" is NULL

AND "PRE_PAY_MONEY" is NULL

AND "CONNECT_TYPE" is NULL

AND "ORDER_LEVEL" is NULL

AND "EXPRESS_COST" is NULL

AND "PACKAGING_MOUTH" is NULL

AND "FIRST_CONFIRM_DATE" = :b103

AND "PRE_PAY_FLAG" is NULL

AND "TIMES" = :b105

AND "SETTLED_FLAG" is NULL

AND "PAY_MOBILE" is NULL

AND "REQUIRE_SEND_DATE" is NULL

AND "CARD_AMOUNT" is NULL

AND "LINKED_ORDER_ID" is NULL

AND "INVOICE_DETAIL_NEED_FLAG" = :b111

AND "EXPORT_FLAG" is NULL

AND "ORIGINAL_HOUSE_ID" is NULL

AND ROWNUM = 1

这里用到了oracle的隐藏参数作为提示，具体产生原因主要是这张新建的表没有任何主键和约束，oracle默认是all column作为key来处理的，并且在目标库也没有最新的statistics，所以oracle自己在处理这样的表的时候就加上了这个隐藏参数提示，最直接的后果就是全表扫描，逻辑读非常高：

具体解决办法如下：

在目标库停掉replicate进程，操作系统里简单的stop命令是停不下来的，我的做法是，在数据库里查询到相应的操作系统进程编号，然后kill掉：

GGSCI (trptdb) 34> info all

Program Status Group Lag at Chkpt Time Since Chkpt

MANAGER RUNNING

REPLICAT ABENDED REP1 00:00:00 00:51:39

然后在目标库m_order_test5表上增加了一个主键：

alter table M_ORDER_TEST5 add constraint M_ORDER_TEST5_pk primary key (order_id);

alter table M_ORDER_TEST5 enable primary key ;

收集下统计资料：

SQL> exec dbms_stats.gather_table_stats('mynet_app','M_ORDER_TEST5');

PL/SQL procedure successfully completed

最后启动replicate进程，又开始欢快的跑起来了：

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn

sda 1.00 0.00 8.00 0 8

sda1 1.00 0.00 8.00 0 8

sda2 0.00 0.00 0.00 0 0

sdb 2.00 0.00 1104.00 0 1104

sdb1 2.00 0.00 1104.00 0 1104

sdb2 0.00 0.00 0.00 0 0

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn

sda 0.00 0.00 0.00 0 0

sda1 0.00 0.00 0.00 0 0

sda2 0.00 0.00 0.00 0 0

sdb 85.00 0.00 9376.00 0 9376

sdb1 85.00 0.00 9376.00 0 9376

sdb2 0.00 0.00 0.00 0 0

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn

sda 0.00 0.00 0.00 0 0

sda1 0.00 0.00 0.00 0 0

sda2 0.00 0.00 0.00 0 0

sdb 0.00 0.00 0.00 0 0

sdb1 0.00 0.00 0.00 0 0

sdb2 0.00 0.00 0.00 0 0

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn

sda 0.00 0.00 0.00 0 0

sda1 0.00 0.00 0.00 0 0

sda2 0.00 0.00 0.00 0 0

sdb 2.00 0.00 1160.00 0 1160

sdb1 2.00 0.00 1160.00 0 1160

sdb2 0.00 0.00 0.00 0 0

最后后续的dml操作也一并应用完毕了。最后提醒大家一下，对于gg来说，最好不要使用create table a as select * from b这样的ddl语句来创建表，会导致2端数据不一致！

记录一下~