前些天客户的ogg延迟到达8小时左右。于是我当时用logdump追踪了一下：
看进程状态：
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
使用logdump
Logdump 254 >open /goldengate/dirdat/sa005160 Current LogTrail is /goldengate/dirdat/sa005160 Logdump 255 >ghdr on Logdump 256 >detail on Logdump 257 >detail data Logdump 258 >usertoken on Logdump 259 >pos 168381460 Reading forward from RBA 168381460 Logdump 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 : 369920 Continued : N (x00) RecCount : 1 (x01) 2014/10/17 16:18:28.000.000 Insert Len 226 RBA 168381460 Name: MW_APP.MWT_UD_KW_SJBGJL After 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 >
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/sa005161 Current LogTrail is /goldengate/dirdat/sa005161 Logdump 262 >ghdr on Logdump 263 >detail on Logdump 264 >detail data Logdump 265 >usertoken on Logdump 266 >pos Current position is RBA 0 Forward Logdump 267 >pos 79119190 Reading forward from RBA 79119190 Logdump 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 : 942196 Continued : N (x00) RecCount : 1 (x01) 2014/10/17 16:24:31.000.000 Insert Len 124 RBA 79119190 Name: MW_APP.MWT_CBM_ZTLBGGL After 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 status Sending 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/sa005165 Current LogTrail is /goldengate/dirdat/sa005165 Logdump 270 >ghdr on Logdump 271 >detail on Logdump 272 >detail data Logdump 273 >usertoken on Logdump 274 >pos 109446515 Reading forward from RBA 109446515 Logdump 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 : 1235984 Continued : N (x00) RecCount : 1 (x01) 2014/10/17 17:12:19.000.000 FieldComp Len 176 RBA 109446515 Name: MW_SYS.MWT_AM_HISMENU After 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
MW_APP用户下的MWT_UD_KW_SJBGJL做大量插入操作没有提交。当日志重用迫使事物提交 所以经过多次切换日志，延迟减小。GGSCI (pmsnxdb1) 100> info all Program Status Group Lag at Chkpt Time Since Chkpt MANAGER RUNNING EXTRACT RUNNING ZBCXY 00:00:00 00:00:03 EXTRACT RUNNING ZBDBA 00:03:46 00:00:09