GoldenGate Lag For Huge Insert, goldengatelag

GoldenGate Lag For Huge Insert, goldengatelag
The customer's ogg was delayed for about 8 hours the other day, so I tracked it with logdump:

View the Process status:
Send extsa staus

EXTRACT ZBDBA (PID 2269368)  Current status: Recovery complete: Processing data with empty data queue  Current read positions:  Redo thread #: 1  Sequence #: 36694  RBA: 35831764  Timestamp: 2014-10-17 16:18:28.000000  SCN: 3044.3022023259  Redo thread #: 2  Sequence #: 34709  RBA: 403776  Timestamp: 2014-10-17 16:18:28.000000  SCN: 3044.3022023265  Current write position:  Sequence #: 5160  RBA: 168381460  Timestamp: 2014-10-17 17:07:07.339050  Extract Trail: ./dirdat/sa

Use logdump

Logdump 254 >open /goldengate/dirdat/sa005160Current LogTrail is /goldengate/dirdat/sa005160Logdump 255 >ghdr onLogdump 256 >detail onLogdump 257 >detail dataLogdump 258 >usertoken onLogdump 259 >pos 168381460Reading forward from RBA 168381460Logdump 260 >n___________________________________________________________________Hdr-Ind    :     E  (x45)     Partition  :     .  (x04) UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41) RecLength  :   226  (x00e2)   IO Time    : 2014/10/17 16:18:28.000.000  IOType     :     5  (x05)     OrigNode   :   255  (xff)TransInd   :     .  (x03)     FormatType :     R  (x52)SyskeyLen  :     0  (x00)     Incomplete :     .  (x00)AuditRBA   :      34709       AuditPos   : 369920Continued  :     N  (x00)     RecCount   :     1  (x01)2014/10/17 16:18:28.000.000 Insert               Len   226 RBA 168381460Name: MW_APP.MWT_UD_KW_SJBGJLAfter  Image:                                             Partition 4   G  s  0000 002c 0000 3641 4431 4545 4239 2d32 3830 382d | ...,..6AD1EEB9-2808- 3437 3030 2d42 4335 322d 4342 3936 4132 4130 4234 | 4700-BC52-CB96A2A0B4 3638 2d30 3537 3137 0001 002c 0000 3641 4431 4545 | 68-05717...,..6AD1EE 4239 2d32 3830 382d 3437 3030 2d42 4335 322d 4342 | B9-2808-4700-BC52-CB 3936 4132 4130 4234 3638 2d30 3537 3132 0002 0028 | 96A2A0B468-05712...( 0000 0024 3436 3930 3238 3835 2d39 3745 462d 3444 | ...$46902885-97EF-4D 3644 2d39 4446 322d 4536 3837 4637 3938 3039 3334 | 6D-9DF2-E687F7980934 Column     0 (x0000), Len    44 (x002c) 0000 3641 4431 4545 4239 2d32 3830 382d 3437 3030 | ..6AD1EEB9-2808-4700 2d42 4335 322d 4342 3936 4132 4130 4234 3638 2d30 | -BC52-CB96A2A0B468-0 3537 3137                                         | 5717 Column     1 (x0001), Len    44 (x002c) 0000 3641 4431 4545 4239 2d32 3830 382d 3437 3030 | ..6AD1EEB9-2808-4700 2d42 4335 322d 4342 3936 4132 4130 4234 3638 2d30 | -BC52-CB96A2A0B468-0 3537 3132                                         | 5712 Column     2 (x0002), Len    40 (x0028) 0000 0024 3436 3930 3238 3835 2d39 3745 462d 3444 | ...$46902885-97EF-4D 3644 2d39 4446 322d 4536 3837 4637 3938 3039 3334 | 6D-9DF2-E687F7980934 Column     3 (x0003), Len    31 (x001f) 0000 3230 3134 2d31 302d 3137 3a31 363a 3138 3a32 | ..2014-10-17:16:18:2 382e 3631 3335 3436 3030 30                       | 8.613546000 Column     4 (x0004), Len     5 (x0005) 0000 0001 30                                      | ....0 Column     5 (x0005), Len    13 (x000d) 0000 0009 3438 3330 3730 3539 38                  | ....483070598 Column     6 (x0006), Len     5 (x0005) 0000 0001 43                                      | ....C Column     7 (x0007), Len     4 (x0004) ffff 0000                                         | .... Column     8 (x0008), Len     4 (x0004) ffff 0000                                         | ....   Logdump 261 >

View table:

   SQL> select count(1) from MW_APP.MWT_UD_KW_SJBGJL;  COUNT(1)----------   1217825      SQL> select count(1) from MW_APP.MWT_UD_KW_SJBGJL;  COUNT(1)----------   1218487  SQL> select count(1) from MW_APP.MWT_UD_KW_SJBGJL;  COUNT(1)----------   1219335  

EXTRACT ZBDBA (PID 2269368)  Current status: Recovery complete: Processing data with empty data queue  Current read positions:  Redo thread #: 1  Sequence #: 36695  RBA: 36154920  Timestamp: 2014-10-17 16:24:31.000000  SCN: 3044.3022349713  Redo thread #: 2  Sequence #: 34712  RBA: 940508  Timestamp: 2014-10-17 16:24:31.000000  SCN: 3044.3022349707  Current write position:  Sequence #: 5161  RBA: 79119190  Timestamp: 2014-10-17 17:15:30.448658  Extract Trail: ./dirdat/sa   Logdump 261 >open /goldengate/dirdat/sa005161Current LogTrail is /goldengate/dirdat/sa005161Logdump 262 >ghdr onLogdump 263 >detail onLogdump 264 >detail dataLogdump 265 >usertoken onLogdump 266 >posCurrent position is RBA 0   ForwardLogdump 267 >pos 79119190Reading forward from RBA 79119190Logdump 268 >n___________________________________________________________________Hdr-Ind    :     E  (x45)     Partition  :     .  (x04) UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41) RecLength  :   124  (x007c)   IO Time    : 2014/10/17 16:24:31.000.000  IOType     :     5  (x05)     OrigNode   :   255  (xff)TransInd   :     .  (x03)     FormatType :     R  (x52)SyskeyLen  :     0  (x00)     Incomplete :     .  (x00)AuditRBA   :      34712       AuditPos   : 942196Continued  :     N  (x00)     RecCount   :     1  (x01)2014/10/17 16:24:31.000.000 Insert               Len   124 RBA 79119190Name: MW_APP.MWT_CBM_ZTLBGGLAfter  Image:                                             Partition 4   G  s  0000 002e 0000 002a 3538 3846 3634 4231 2d37 3938 | .......*588F64B1-798 452d 3444 3131 2d41 3930 332d 3546 3446 4130 4632 | E-4D11-A903-5F4FA0F2 3236 3033 2d33 3634 3938 0001 000d 0000 0009 3438 | 2603-36498........48 3331 3238 3538 3300 0200 04ff ff00 0000 0300 04ff | 3128583............. ff00 0000 0400 04ff ff00 0000 0500 15ff ff31 3930 | .................190 302d 3031 2d30 313a 3030 3a30 303a 3030 0006 0004 | 0-01-01:00:00:00.... ffff 0000                                         | .... Column     0 (x0000), Len    46 (x002e) 0000 002a 3538 3846 3634 4231 2d37 3938 452d 3444 | ...*588F64B1-798E-4D 3131 2d41 3930 332d 3546 3446 4130 4632 3236 3033 | 11-A903-5F4FA0F22603 2d33 3634 3938                                    | -36498 Column     1 (x0001), Len    13 (x000d) 0000 0009 3438 3331 3238 3538 33                  | ....483128583 Column     2 (x0002), Len     4 (x0004) ffff 0000                                         | .... Column     3 (x0003), Len     4 (x0004) ffff 0000                                         | .... Column     4 (x0004), Len     4 (x0004) ffff 0000                                         | .... Column     5 (x0005), Len    21 (x0015) ffff 3139 3030 2d30 312d 3031 3a30 303a 3030 3a30 | ..1900-01-01:00:00:0 30                                                | 0 Column     6 (x0006), Len     4 (x0004) ffff 0000                                        SQL> SQL> select count(1) from MW_APP.MWT_UD_KW_SJBGJL;  COUNT(1)----------   1220223    GGSCI (pmsnxdb1) 97> !send ZBDBA statusSending STATUS request to EXTRACT ZBDBA ...EXTRACT ZBDBA (PID 2269368)  Current status: Recovery complete: Processing data  Current read positions:  Redo thread #: 1  Sequence #: 36700  RBA: 4528776  Timestamp: 2014-10-17 17:18:05.000000  SCN: 3044.3023151974  Redo thread #: 2  Sequence #: 34724  RBA: 87547776  Timestamp: 2014-10-17 17:18:06.000000  SCN: 3044.3023152070  Current write position:  Sequence #: 5165  RBA: 109446515  Timestamp: 2014-10-17 17:29:26.994375  Extract Trail: ./dirdat/sa Logdump 269 >open /goldengate/dirdat/sa005165Current LogTrail is /goldengate/dirdat/sa005165Logdump 270 >ghdr onLogdump 271 >detail onLogdump 272 >detail dataLogdump 273 >usertoken onLogdump 274 >pos 109446515Reading forward from RBA 109446515Logdump 275 >n___________________________________________________________________Hdr-Ind    :     E  (x45)     Partition  :     .  (x04) UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41) RecLength  :   176  (x00b0)   IO Time    : 2014/10/17 17:12:19.000.000  IOType     :    15  (x0f)     OrigNode   :   255  (xff)TransInd   :     .  (x03)     FormatType :     R  (x52)SyskeyLen  :     0  (x00)     Incomplete :     .  (x00)AuditRBA   :      34724       AuditPos   : 1235984Continued  :     N  (x00)     RecCount   :     1  (x01)2014/10/17 17:12:19.000.000 FieldComp            Len   176 RBA 109446515Name: MW_SYS.MWT_AM_HISMENUAfter  Image:                                             Partition 4   G  s  0000 0026 0000 4245 4642 4246 3243 2d45 3532 342d | ...&..BEFBBF2C-E524- 3441 3641 2d39 3738 412d 3233 3545 3343 3431 3744 | 4A6A-978A-235E3C417D 4439 0001 0026 0000 4436 4539 3631 4545 2d36 4331 | D9...&..D6E961EE-6C1 362d 3437 3138 2d41 4135 342d 3245 3146 3738 4531 | 6-4718-AA54-2E1F78E1 4441 4145 0002 0007 0000 0003 3238 3200 0300 1f00 | DAAE........282..... 0032 3031 312d 3034 2d31 313a 3038 3a35 303a 3239 | .2011-04-11:08:50:29 2e32 3637 3030 3030 3030 0004 0003 0000 4300 0500 | .267000000......C... Column     0 (x0000), Len    38 (x0026) 0000 4245 4642 4246 3243 2d45 3532 342d 3441 3641 | ..BEFBBF2C-E524-4A6A 2d39 3738 412d 3233 3545 3343 3431 3744 4439      | -978A-235E3C417DD9 Column     1 (x0001), Len    38 (x0026) 0000 4436 4539 3631 4545 2d36 4331 362d 3437 3138 | ..D6E961EE-6C16-4718 2d41 4135 342d 3245 3146 3738 4531 4441 4145      | -AA54-2E1F78E1DAAE Column     2 (x0002), Len     7 (x0007) 0000 0003 3238 32                                 | ....282 Column     3 (x0003), Len    31 (x001f) 0000 3230 3131 2d30 342d 3131 3a30 383a 3530 3a32 | ..2011-04-11:08:50:2 392e 3236 3730 3030 3030 30                       | 9.267000000 Column     4 (x0004), Len     3 (x0003) 0000 43                                           | ..C Column     5 (x0005), Len    14 (x000e) 0000 000a b9a4 d7f7 c6b1 b9dc c0ed                | .............. Column     6 (x0006), Len     4 (x0004) ffff 0000                                         | .... Column     7 (x0007), Len     9 (x0009) 0000 0005 3939 3434 32                            | ....99442   

MWT_UD_KW_SJBGJL under the MW_APP user does a lot of insert operations and is not submitted. When log reuse forces transactions to be submitted, the latency decreases after multiple log switching. GGSCI (pmsnxdb1) 100> info allProgram Status Group Lag at Chkpt Time Since ChkptMANAGER running extract running zbcxy 00:00:00 extract running zbdba 00:00:03