OGG extract process hung

清明节放假的第一天,某客户的ogg出现异常,通过vpn简单看了一下,发现是有用ogg文件系统空间使用率达到100%之后,导致ogg extract 进程abend。然而当我清理掉部分空间之后,启动extract进程,却发现进程的checkpoint一直不变化,很明显;这是ogg extract hung了。

首先我们来看下当前extract process的信息:

GGSCI (nxcrmdb1) 9> info EXTEA

EXTRACT    EXTEA     Last Started 2016-04-02 09:20   Status RUNNING
Checkpoint Lag       05:37:48 (updated 00:00:02 ago)
Log Read Checkpoint  Oracle Redo Logs
                     2016-04-02 03:44:03  Thread 1, Seqno 175338, RBA 41207712
                     SCN 3427.2063782250 (14720916705642)
Log Read Checkpoint  Oracle Redo Logs
                     2016-04-02 03:44:04  Thread 2, Seqno 99720, RBA 894241852
                     SCN 3427.2063783497 (14720916706889)

 

我们可以发现,启动extract 进程之后,checkpoint时间点一直没有移动过。

由于前不久处理过一个类似的问题,ogg 版本也是11.2版本,因此这里仍然采取直接将进程kill -9杀掉,然后再次启动extract 进程,我发现3个extract 进程中有一个是能够启动的,而且状态正常。但是另外2个extract 进程虽然能够起来,但是checkpoint 信息仍然不变化。

无奈之下这里只能将这2个extract 进程的时间点进行后退,以此来解决extract process hung的问题。实际上这个处理方式并不会导致目标端出现数据差异。操作命令比较简单,如下所示:

ALTER EXTRACT EX_GA, THREAD 1,BEGIN 2016-04-02 03:45:23
ALTER EXTRACT EX_GA, THREAD 2,BEGIN 2016-04-02 03:45:23

 

解决了源端的extract 进程之后,我进一步检查目标端的replicat进程发现有个复制进程无法启动,状态如下:

GGSCI (CRM_FWKT_RZ) 12> info RP_ALL

REPLICAT   RP_ALL    Last Started 2016-04-02 10:31   Status ABENDED
Checkpoint Lag       00:00:00 (updated 00:50:33 ago)
Log Read Checkpoint  File ./dirdat/ru001386
                     2016-04-02 09:34:49.390992  RBA 1082

 

我们进一步来看下该复制进程的报错信息如何:

2016-04-02 10:29:38  WARNING OGG-00869  OCI Error ORA-00001: unique constraint (BASE_GG.PK_PROD_INST_ATTR) violated (status = 1), SQL <INSERT /*+ RESTRICT_ALL_REF_CONS */ INTO "BASE_GG"."PROD_
INST_ATTR" ("PROD_INST_ATTR_ID","PROD_INST_ID","ATTR_ID","ATTR_VALUE_ID","ATTR_VALUE","STATUS_CD","STATUS_DATE","EFF_DATE","EXP_DATE","CREATE_D>.

2016-04-02 10:29:38  WARNING OGG-01004  Aborted grouped transaction on 'BASE_GG.PROD_INST_ATTR', Database error 1 (OCI Error ORA-00001: unique constraint (BASE_GG.PK_PROD_INST_ATTR) violated (
status = 1), SQL <INSERT /*+ RESTRICT_ALL_REF_CONS */ INTO "BASE_GG"."PROD_INST_ATTR" ("PROD_INST_ATTR_ID","PROD_INST_ID","ATTR_ID","ATTR_VALUE_ID","ATTR_VALUE","STATUS_CD","STATUS_DATE","EFF_
DATE","EXP_DATE","CREATE_D>).

2016-04-02 10:29:38  WARNING OGG-01003  Repositioning to rba 1142 in seqno 1386.

2016-04-02 10:29:38  WARNING OGG-01154  SQL error 1 mapping CRMV2.PROD_INST_ATTR to BASE_GG.PROD_INST_ATTR OCI Error ORA-00001: unique constraint (BASE_GG.PK_PROD_INST_ATTR) violated (status =
 1), SQL <INSERT /*+ RESTRICT_ALL_REF_CONS */ INTO "BASE_GG"."PROD_INST_ATTR" ("PROD_INST_ATTR_ID","PROD_INST_ID","ATTR_ID","ATTR_VALUE_ID","ATTR_VALUE","STATUS_CD","STATUS_DATE","EFF_DATE","E
XP_DATE","CREATE_D>.

2016-04-02 10:29:38  WARNING OGG-01003  Repositioning to rba 1142 in seqno 1386.

Source Context :
  SourceModule            : [er.main]
  SourceID                : [/scratch/aime2/adestore/views/aime2_staxk11/oggcore/OpenSys/src/app/er/rep.c]
  SourceFunction          : [take_rep_err_action(short, int32_t, const char *, extr_ptr_def *, std_rec_hdr_def *, char *, file_def *, bool)]
  SourceLine              : [16148]

2016-04-02 10:29:38  ERROR   OGG-01296  Error mapping from CRMV2.PROD_INST_ATTR to BASE_GG.PROD_INST_ATTR.

***********************************************************************
*                   ** Run Time Statistics **                         *
***********************************************************************

Reading ./dirdat/ru001386, current RBA 1142, 0 records

Report at 2016-04-02 10:29:38 (activity since 2016-04-02 10:29:37)

From Table CRMV2.PROD_INST_ATTR to BASE_GG.PROD_INST_ATTR:
       #                   inserts:         0
       #                   updates:         0
       #                   deletes:         0
       #                  discards:         1

 

我们看到,这里的关键错误是OGG-01296,从字面意思来讲,不难理解。这表示目标端需要进行相应的操作,却发现无法进行相关的匹配操作;实际上该错误通常发现在update和delete操作上。最常见的原因莫过于在目标端找不到对应的记录进行update或delete操作;到时replicate进程出现异常。

那么问题来了?我们如何知道报错的操作到底是什么操作呢?实际上goldengate提供了一个内置的日志dump工具,那就是logdump。我们可以利用该工具来进行进一步深入分析:

[CRM_FWKT_RZ@/realsync/crmgg/ogg]./logdump

Oracle GoldenGate Log File Dump Utility
Version 11.1.1.1.2 OGGCORE_11.1.1.1.2_PLATFORMS_111004.2100 

Copyright (C) 1995, 2011, Oracle and/or its affiliates. All rights reserved.


 
Logdump 1 >ghdr on
Logdump 2 >detail on
Logdump 3 >open ./dirdat/ru001386
Current LogTrail is /realsync/crmgg/ogg/dirdat/ru001386 
Logdump 4 >pos 1142
Reading forward from RBA 1142 
Logdump 5 >n
___________________________________________________________________ 
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)  
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)  
RecLength  :   305  (x0131)   IO Time    : 2016/04/02 03:44:00.001.894   
IOType     :     5  (x05)     OrigNode   :   255  (xff) 
TransInd   :     .  (x00)     FormatType :     R  (x52) 
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00) 
AuditRBA   :      99720       AuditPos   : 818519620 
Continued  :     N  (x00)     RecCount   :     1  (x01) 

2016/04/02 03:44:00.001.894 Insert               Len   305 RBA 1142 
Name: CRMV2.PROD_INST_ATTR 
After  Image:                                             Partition 4   G  b   
 0000 000a 0000 0000 0000 5452 f400 0001 000a 0000 | ..........TR........  
 0000 0000 1f9d 2c88 0002 000a 0000 0000 0000 0006 | ......,.............  
 cbab 0003 000a ffff 0000 0000 0000 0000 0004 0005 | ....................  
 0000 0001 3100 0500 0800 0000 0431 3030 3000 0600 | ....1........1000...  
 1500 0032 3031 362d 3034 2d30 323a 3033 3a34 343a | ...2016-04-02:03:44:  
 3030 0007 0015 0000 3230 3136 2d30 342d 3032 3a30 | 00......2016-04-02:0  
 333a 3434 3a30 3000 0800 1500 0032 3139 392d 3031 | 3:44:00......2199-01  
Column     0 (x0000), Len    10 (x000a)  
Column     1 (x0001), Len    10 (x000a)  
Column     2 (x0002), Len    10 (x000a)  
Column     3 (x0003), Len    10 (x000a)  
Column     4 (x0004), Len     5 (x0005)  
Column     5 (x0005), Len     8 (x0008)  
Column     6 (x0006), Len    21 (x0015)  
Column     7 (x0007), Len    21 (x0015)  
Column     8 (x0008), Len    21 (x0015)  
Column     9 (x0009), Len    21 (x0015)  
Column    10 (x000a), Len    21 (x0015)  
Column    11 (x000b), Len     4 (x0004)  
Column    12 (x000c), Len    10 (x000a)  
Column    13 (x000d), Len    10 (x000a)  
Column    14 (x000e), Len    10 (x000a)  
Column    15 (x000f), Len    10 (x000a)  
Column    16 (x0010), Len    21 (x0015)  
Column    17 (x0011), Len    10 (x000a)  
   
Logdump 6 >
Logdump 6 >n
___________________________________________________________________ 
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)  
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)  
RecLength  :    92  (x005c)   IO Time    : 2016/04/02 03:44:00.001.894   
IOType     :    15  (x0f)     OrigNode   :   255  (xff) 
TransInd   :     .  (x02)     FormatType :     R  (x52) 
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00) 
AuditRBA   :      99720       AuditPos   : 820950124 
Continued  :     N  (x00)     RecCount   :     1  (x01) 

2016/04/02 03:44:00.001.894 FieldComp            Len    92 RBA 1580 
Name: CRMV2.PROD_INST 
After  Image:                                             Partition 4   G  e   
 0000 000a 0000 0000 0000 1f9d 2c88 0012 000a 0000 | ............,.......  
 0006 3132 3030 3030 0014 0015 0000 3230 3136 2d30 | ..120000......2016-0  
 342d 3032 3a30 333a 3434 3a30 3000 1500 1500 0032 | 4-02:03:44:00......2  
 3031 362d 3034 2d30 323a 3033 3a34 343a 3030 001b | 016-04-02:03:44:00..  
 000a 0000 0000 0000 0000 c8f7                     | ............  
Column     0 (x0000), Len    10 (x000a)  
Column    18 (x0012), Len    10 (x000a)  
Column    20 (x0014), Len    21 (x0015)  
Column    21 (x0015), Len    21 (x0015)  
Column    27 (x001b), Len    10 (x000a)  

Logdump 7 >n
___________________________________________________________________ 
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)  
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)  
RecLength  :   305  (x0131)   IO Time    : 2016/04/02 03:44:00.001.894   
IOType     :     5  (x05)     OrigNode   :   255  (xff) 
TransInd   :     .  (x00)     FormatType :     R  (x52) 
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00) 
AuditRBA   :      99720       AuditPos   : 819637792 
Continued  :     N  (x00)     RecCount   :     1  (x01) 

2016/04/02 03:44:00.001.894 Insert               Len   305 RBA 1766 
Name: CRMV2.PROD_INST_ATTR 
After  Image:                                             Partition 4   G  b   
 0000 000a 0000 0000 0000 5452 f401 0001 000a 0000 | ..........TR........  
 0000 0000 1f62 f526 0002 000a 0000 0000 0000 0006 | .....b.&............  
 cbab 0003 000a ffff 0000 0000 0000 0000 0004 0005 | ....................  
 0000 0001 3100 0500 0800 0000 0431 3030 3000 0600 | ....1........1000...  
 1500 0032 3031 362d 3034 2d30 323a 3033 3a34 343a | ...2016-04-02:03:44:  
 3030 0007 0015 0000 3230 3136 2d30 342d 3032 3a30 | 00......2016-04-02:0  
 333a 3434 3a30 3000 0800 1500 0032 3139 392d 3031 | 3:44:00......2199-01  
Column     0 (x0000), Len    10 (x000a)  
Column     1 (x0001), Len    10 (x000a)  
Column     2 (x0002), Len    10 (x000a)  
Column     3 (x0003), Len    10 (x000a)  
Column     4 (x0004), Len     5 (x0005)  
Column     5 (x0005), Len     8 (x0008)  
Column     6 (x0006), Len    21 (x0015)  
Column     7 (x0007), Len    21 (x0015)  
Column     8 (x0008), Len    21 (x0015)  
Column     9 (x0009), Len    21 (x0015)  
Column    10 (x000a), Len    21 (x0015)  
Column    11 (x000b), Len     4 (x0004)  
Column    12 (x000c), Len    10 (x000a)  
Column    13 (x000d), Len    10 (x000a)  
Column    14 (x000e), Len    10 (x000a)  
Column    15 (x000f), Len    10 (x000a)  
Column    16 (x0010), Len    21 (x0015)  
Column    17 (x0011), Len    10 (x000a)  
Logdump 8 >SFET
End of Transaction found at RBA 2204 
___________________________________________________________________ 
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)  
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)  
RecLength  :    92  (x005c)   IO Time    : 2016/04/02 03:44:00.001.894   
IOType     :    15  (x0f)     OrigNode   :   255  (xff) 
TransInd   :     .  (x02)     FormatType :     R  (x52) 
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00) 
AuditRBA   :      99720       AuditPos   : 820966172 
Continued  :     N  (x00)     RecCount   :     1  (x01) 

2016/04/02 03:44:00.001.894 FieldComp            Len    92 RBA 2204 
Name: CRMV2.PROD_INST 
After  Image:                                             Partition 4   G  e   
 0000 000a 0000 0000 0000 1f62 f526 0012 000a 0000 | ...........b.&......  
 0006 3132 3030 3030 0014 0015 0000 3230 3136 2d30 | ..120000......2016-0  
 342d 3032 3a30 333a 3434 3a30 3000 1500 1500 0032 | 4-02:03:44:00......2  
 3031 362d 3034 2d30 323a 3033 3a34 343a 3030 001b | 016-04-02:03:44:00..  
 000a 0000 0000 0000 0000 c8f7                     | ............  
Column     0 (x0000), Len    10 (x000a)  
Column    18 (x0012), Len    10 (x000a)  
Column    20 (x0014), Len    21 (x0015)  
Column    21 (x0015), Len    21 (x0015)  
Column    27 (x001b), Len    10 (x000a)  

 

这里对于logdump 的操作使用,我不做过多的描述。我们根据ogg的告警信息可以看出问题出在偏移量1422,因此我们logdump时,以此来起点进行分析,可以发现操作的事务其实都是insert操作。对于insert操作,为什么会出现这个错误呢?这还是有些让人难以理解。

实际上我们细想一下,我们可以发现,Oracle中数据的校验,不仅仅是单条;比如相关的表存在主外键约束,存在相互依赖的数据,那么就很可能出现这种情况。实际上我们也发现,上述logdump的事务信息中,涉及到2个表的insert操作。

这里我们下不去纠结数据的不一致性,首先去解决问题。

对于这个问题,解决的方法其实有2种:

1、使用HANDLECOLLISIONS 参数

2、将涉及的2个表进行数据重新初始化,或者跳过这个事务,然后手工将这个事务的数据进行同步。

这里我为了省事,选择了第一种解决方案;实际上,大多数情况之下,我们应该选择第2种解决方案,只是相对复杂一下。

 

发表评论

电子邮件地址不会被公开。 必填项已用*标注