7 Replies Latest reply: Mar 25, 2014 10:09 AM by AntonyLosev RSS

    OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead

    AntonyLosev

      Hello, dear community!

       

      Today I hit the strange error while replicating from MS SQL Sever 2005 (pre CU6) to Oracle 11.2.0.4.

      The error is on the source site.

      First extract abended with the following message:

       

      TABLE resolved (entry dbo.EventMaster):
        table dbo.EventMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      Using the following key columns for source table dbo.EventMaster: id.
      
      
      Source Context :
        SourceModule            : [ggvam.gen]
        SourceID                : [../gglib/ggvam/cvamgen.cpp]
        SourceFunction          : [com_goldengate_vam::CVamGen::vamRead]
        SourceLine              : [689]
        ThreadBacktrace         : [9] elements
                                : [gglog.dll(??1CContextItem@@UEAA@XZ+0x32e2) [0x0000000180109C42]]
                                : [gglog.dll(?_MSG_ERR_VAM_API_ERROR_MSG@@YAPEAVCMessage@@PEAVCSourceContext@@PEBDH1W4MessageDisposition@CMessageFactory@@@Z+0xde) [0x000000018002C00E]]
                                : [extract.exe(GGDataBufferGetNextChunk+0x534d5) [0x0000000140248485]]
                                : [extract.exe(GGDataBufferGetNextChunk+0x61d) [0x00000001401F55CD]]
                                : [extract.exe(<GDataBufferGetNextChunk+0x61d) [0x000000014000D6EE]]
                                : [extract.exe(shutdownMonitoring+0x1f28) [0x00000001400C87E8]]
                                : [extract.exe(shutdownMonitoring+0x1c1ea) [0x00000001400E2AAA]]
                                : [extract.exe(VAMRead+0x92850) [0x0000000140335DB0]]
                                : [kernel32.dll(BaseProcessStart+0x2c) [0x0000000077D5969C]]
      
      2014-02-19 06:44:31  ERROR   OGG-00146  VAM function VAMRead returned unexpected result: error 600 - VAM Client Report <[mssqlvam::MetadataResolver2K5::InternalGetColumns] Timeout expired Error (-2147217871): Timeout expired
      >.
      
      2014-02-19 06:44:31  INFO    OGG-00178  VAM Client Report <Last LSN Read: 001818b5:00009c04:0004
      Open Transactions
      -----------------
      0x0000:2e1c3a72 (2014/02/19 06:43:47.500) @ 001818b5:000082d2:0007: Upd(Comp) = 2(0), Row(comp) = 5(0)
      0x0000:2e1c3a7a (2014/02/19 06:43:47.703) @ 001818b5:00009c04:0003: Upd(Comp) = 0(0), Row(comp) = 0(0)
      >.
      
      2014-02-19 06:44:31  INFO    OGG-00178  VAM Client Report <Sanity checking is not enabled.
      >.
      
      ***********************************************************************
      *                   ** Run Time Statistics **                         *
      ***********************************************************************
      
      
      Report at 2014-02-19 06:44:31 (activity since 2014-02-18 13:06:21)
      
      Output to C:\GoldenGate\dirdat\E1:
      
      From Table dbo.ShipmentHeader:
             #                   inserts:        43
             #                   updates:      8144
             #                   befores:      8144
             #                   deletes:       219
             #                  discards:         0
      
      
      
      ...
      ...
      
      

      ...

       

      No records were replicated from dbo.EventMaster

       

      This happened after I included several new tables into replication. And everything ran fine for several hours

      PRM contents:

      extract E1
      SETENV (GGS_CacheRetryCount = 100)
      SETENV (GGS_CacheRetryDelay = 5000)
      sourcedb GGODBC, userid GGATE, password !@cGate34
      discardfile C:\GoldenGate\dirrpt\E1.dsc, purge
      exttrail C:\GoldenGate\dirdat\E1
      tranlogoptions managesecondarytruncationpoint
      nocompressupdates
      nocompressdeletes
      getupdatebefores
      table dbo.LPNHeader , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.LPNHeaderJournal , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderDetail , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderHeader , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderHeaderEvent , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderHeaderSchedule , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderShipmentHeader , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrderShipmentLPN , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.OrgMaster , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ScheduleCode , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ScheduleDetail , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ScheduleEvent , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ScheduleHeader , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.Sys_code , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.UserMaster , tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.EventHeader, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.EventMaster, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ShipmentHeader, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ShipmentHeaderEvent, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.LocationMaster, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      
      

       

      Trandata was successfully added for new tables.

       

      After trying to restart extract it began to abend without any error message in RPT files:

      ***********************************************************************
                     Oracle GoldenGate Capture for SQL Server
           Version 11.2.1.0.2 OGGCORE_11.2.1.0.2T3_PLATFORMS_120724.2205
      Windows x64 (optimized), Microsoft SQL Server on Jul 25 2012 04:00:23
      
      Copyright (C) 1995, 2012, Oracle and/or its affiliates. All rights reserved.
      
      
                          Starting at 2014-02-19 12:08:22
      ***********************************************************************
      
      Operating System Version:
      Microsoft Windows Server 2003 R2, Enterprise x64 Edition, on x64
      Version 5.2 (Build 3790: Service Pack 2)
      
      Process id: 7516
      
      Description:
      
      ***********************************************************************
      **            Running with the following parameters                  **
      ***********************************************************************
      
      2014-02-19 12:08:22  INFO    OGG-03035  Operating system character set identified as windows-1252. Locale: en_US, LC_ALL:.
      extract E1
      SETENV (GGS_CacheRetryCount = 100)
      Set environment variable (GGS_CacheRetryCount=100)
      SETENV (GGS_CacheRetryDelay = 5000)
      Set environment variable (GGS_CacheRetryDelay=5000)
      sourcedb GGODBC, userid GGATE, password *********
      
      2014-02-19 12:08:22  INFO    OGG-03036  Database character set identified as windows-1252. Locale: en_US.
      
      2014-02-19 12:08:22  INFO    OGG-03037  Session character set identified as windows-1252.
      discardfile C:\GoldenGate\dirrpt\E1.dsc, purge
      exttrail C:\GoldenGate\dirdat\E1
      tranlogoptions managesecondarytruncationpoint
      nocompressupdates
      nocompressdeletes
      getupdatebefores
      table dbo.EventHeader, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.EventMaster, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ShipmentHeader, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.ShipmentHeaderEvent, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      table dbo.LocationMaster, tokens (
      TKN-XID = @getenv( "TRANSACTION", "XID"),
      TKN-CSN = @getenv( "TRANSACTION", "CSN"),
      TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
      
      2014-02-19 12:08:22  INFO    OGG-01815  Virtual Memory Facilities for: COM
          anon alloc: MapViewOfFile  anon free: UnmapViewOfFile
          file alloc: MapViewOfFile  file free: UnmapViewOfFile
          target directories:
          C:\GoldenGate\dirtmp.
      
      CACHEMGR virtual memory values (may have been adjusted)
      CACHESIZE:                               64G
      CACHEPAGEOUTSIZE (normal):                8M
      PROCESS VM AVAIL FROM OS (min):         128G
      CACHESIZEMAX (strict force to disk):     96G
      
      Database Version:
      Microsoft SQL Server
      Version 09.00.3042
      ODBC Version 03.52.0000
      
      Driver Information:
      SQLNCLI.DLL
      Version 09.00.3042
      ODBC Version 03.52
      
      2014-02-19 12:08:23  INFO    OGG-01052  No recovery is required for target file C:\GoldenGate\dirdat\E1000286, at RBA 0 (file not opened).
      
      2014-02-19 12:08:23  INFO    OGG-01478  Output file C:\GoldenGate\dirdat\E1 is using format RELEASE 11.2.
      
      2014-02-19 12:08:23  INFO    OGG-00182  VAM API running in single-threaded mode.
      
      2014-02-19 12:08:23  INFO    OGG-01515  Positioning to begin time Feb 19, 2014 4:30:00 AM.
      
      2014-02-19 12:08:23  INFO    OGG-00178  VAM Client Report <Opening files for DSN: GGODBC, Server: SQL, Database: EEM2008>.
      
      2014-02-19 12:08:23  INFO    OGG-00178  VAM Client Report <Running in MSSQL2005 mode.>.
      
      2014-02-19 12:08:24  INFO    OGG-01560  Positioned to TIME: 2014-02-19 05:30:02.060000 NextReadLsn: 0x001816bc:00003c58:0001 EOL: false.
      
      ***********************************************************************
      **                     Run Time Messages                             **
      ***********************************************************************
      
      
      2014-02-19 12:08:24  INFO    OGG-01517  Position of first record processed LSN: 0x001816bc:00003c58:0001, Tran: 0000:2e1c0ab5, Feb 19, 2014 4:30:02 AM.
      
      

       

      After this point it abends. I clearly see the process starting and then going down in the Task Manger. It starts, eats 71 Mb of virtual memory and goes away.

      The RPT I'm showing is after I desperately issued alter extract, begin 2014-02-19 05:30:00. But ones before were like this one.

       

      I've tried to create another extracts with the same list of tables, tried to shorten the list to 5 tables that were replicating fine for 3 months before today, tired to etrollover extract.

      Datapump extracts are working fine on the same server, plus I've tried to run Inital replication task and I finished without errors.

       

      Here are trace and trace2 files:

       

      These one are for a new extract that I added. I works on the subset of original tables and is set to start at 5.30 AM.

      For the new extract I added the same trail file E1, but created with seqno 287 (that seqno does not interfere with original extract's seqno).

      After each start of a new replicat it rollovers to the new seqno (why it does is a mystery to me).

      I'll try to add extract pointing to another (new) trail, but I'm almost sure that that will not help.

       

      TRACE

      Trace starting at 2014-02-19 Wed Russian Standard Time 16:18:32
      
      16:18:35.428 (2843) entering VAMInitialize
      16:18:36.163 (3578) exited VAMInitialize
      16:18:36.163 (3578) entering process_extract_loop
      16:18:36.163 (3578) entering checkpoint_position
      16:18:36.163 (3578) exiting checkpoint_position
      16:18:36.163 (3578) entering VAMControl
      16:18:36.163 (3578) exited VAMControl
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      
      

       

      TRACE2

      
      Trace starting at 2014-02-19 Wed Russian Standard Time 16:18:32
      
      16:18:32.585 (0) Processing infile param [sourcedb GGODBC, userid GGATE, password !@cGate34]...
      16:18:32.678 (93) Processing infile param [discardfile C:\GoldenGate\dirrpt\E3.dsc, purge]...
      16:18:32.678 (93) Processing infile param [exttrail C:\GoldenGate\dirdat\E1]...
      16:18:32.678 (93) Processing infile param [tranlogoptions managesecondarytruncationpoint]...
      16:18:32.678 (93) Processing infile param [nocompressupdates]...
      16:18:32.678 (93) Processing infile param [nocompressdeletes]...
      16:18:32.694 (109) Processing infile param [getupdatebefores]...
      16:18:32.694 (109) Processing infile param [table dbo.EventHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Wildcard processing for [table dbo.EventHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Finished wildcard processing for [table dbo.EventHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Processing infile param [table dbo.EventMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Wildcard processing for [table dbo.EventMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Finished wildcard processing for [table dbo.EventMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Processing infile param [table dbo.ShipmentHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Wildcard processing for [table dbo.ShipmentHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Finished wildcard processing for [table dbo.ShipmentHeader, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Processing infile param [table dbo.ShipmentHeaderEvent, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Wildcard processing for [table dbo.ShipmentHeaderEvent, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Finished wildcard processing for [table dbo.ShipmentHeaderEvent, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Processing infile param [table dbo.LocationMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Wildcard processing for [table dbo.LocationMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:32.710 (125) Finished wildcard processing for [table dbo.LocationMaster, tokens ( TKN-XID = @getenv( "TRANSACTION", "XID"), TKN-CSN = @getenv( "TRANSACTION", "CSN"), TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores]...
      16:18:33.913 (1328) Read infile params...
      16:18:33.913 (1328) Done with DB version/login...
      16:18:33.913 (1328) Allocated sql statatements...
      16:18:33.913 (1328) Got checkpoint context...
      16:18:35.413 (2828) Done with data source determination...
      16:18:35.428 (2843) Opening files...
      16:18:35.428 (2843) *** Initializing performance stats ***
      16:18:35.428 (2843) entering VAMInitialize
      16:18:36.163 (3578) exited VAMInitialize
      16:18:36.163 (3578) Processing files...
      16:18:36.163 (3578) entering process_extract_loop
      16:18:36.163 (3578) entering checkpoint_position
      16:18:36.163 (3578) exiting checkpoint_position
      16:18:36.163 (3578) entering VAMControl
      16:18:36.163 (3578) exited VAMControl
      16:18:36.163 (3578) entering IPC_read_TCP with hndl->ip.sock 18446744073709551615 and listen_sock 408
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) time spent executing VAMRead 0.00% (execute=0.000,total=3.578,count=10)
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) exited READ_EXTRACT_RECORD (stat=520, seqno=0, rba=0)
      16:18:36.163 (3578) * --- entering READ_EXTRACT_RECORD --- *
      16:18:36.163 (3578) entering VAMRead
      16:18:36.163 (3578) exited VAMRead
      16:18:36.163 (3578) entering VAMRead
      
      

       

      Also I've tried the following (from Installation and Setup Guide for SQL Server).

      If the Extract process running against a pre-CU6 source is suspended for a longer

      time than the normal log backup frequency, you will need to re-enable and start the

      SQL Server Replication Log Reader Agent job temporarily to manage the last

      distributed transaction. Stop and disable the job before you restart Extract.

      But the job never finished, I had to stop and to disable it.

       

      So far nothing helped.

       

      Database log backup was successfully done at 5:00 AM.

       

      The database is in heavy testing mode, so I can't simply restart database or server.

       

      Begging for your help!

        • 1. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
          MikeN

          This does not answer your question, but rather is just a comment on your extract prm file:

           

          This entire section:

           

          getupdatebefores 
          table dbo.LPNHeader , tokens ( 
          TKN-XID = @getenv( "TRANSACTION", "XID"), 
          TKN-CSN = @getenv( "TRANSACTION", "CSN"), 
          TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores; 
          etc...
          table dbo.LocationMaster, tokens ( 
          TKN-XID = @getenv( "TRANSACTION", "XID"), 
          TKN-CSN = @getenv( "TRANSACTION", "CSN"), 
          TKN-RSN = @getenv( "RECORD", "RSN" )), getupdatebefores;
          

           

          Can, I believe, simply be replaced with this :

           

          getUpdateBefores
          table dbo.LPNHeader;
          table dbo.LPNHeaderJournal;
          table dbo.OrderDetail;
          table dbo.OrderHeader;
          table dbo.OrderHeaderEvent;
          table dbo.OrderHeaderSchedule;
          table dbo.OrderShipmentHeader;
          table dbo.OrderShipmentLPN;
          table dbo.OrgMaster;
          table dbo.ScheduleCode;
          table dbo.ScheduleDetail;
          table dbo.ScheduleEvent;
          table dbo.ScheduleHeader;
          table dbo.Sys_code;
          table dbo.UserMaster;
          table dbo.EventHeader;
          table dbo.EventMaster;
          table dbo.ShipmentHeader;
          table dbo.ShipmentHeaderEvent;
          table dbo.LocationMaster;
          

           

          ...since, the tokens you are storing for the "getenv" values  are actually already stored in the trail, and can be retrieved (using "getenv") downstream without using tokens.  (You might want to double-check that this is the case, though.)

          Although that doesn't answer the question, perhaps the simplified prm file might make it easier to troubleshoot the problem.  (Sorry, I don't have any input on that.)

          • 2. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
            AntonyLosev

            Thanks, Mike!

             

            I took this part from RittmanMead, from their article on realtime datawarehousing. They clearly stated that XID, CSN and RSN can be properly captured only on the source side, so they ought to be stored as tokens. I will double check this.

             

            Regards, Anton

            • 3. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
              AntonyLosev

              Mike, I have checked the reference. It seems that guys from RittmanMead were right.

              For my current version (11.2.0.3) GG Reference states

               

              Using the TRANSACTION information type

              Use the TRANSACTION option of @GETENV to return information about a source transaction.

              This option is valid for the Extract process.

               

              Regards, Anton

              • 4. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
                Himachalapathy-Oracle

                Try to add the following command and see if the extract is able to move

                TRANLOGOPTIONS NODDLCHANGEWARNING

                • 5. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
                  AntonyLosev

                  Thanks for the advice.

                  Tried this clause upon hitting error once again but it did not help.

                   

                  Seems that GG can't operate properly with SQL Server when it has it's log backed up.

                  • 6. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
                    MikeN

                    AntonyLosev wrote:

                    Thanks for the advice.

                    Tried this clause upon hitting error once again but it did not help.

                    Seems that GG can't operate properly with SQL Server when it has it's log backed up.

                     

                    Has Oracle GoldenGate Support been able to provide an answer? The error seems rather straight-foward to diagnose, assuming there's an existing support note documenting the issue:

                    ERROR   OGG-00146  VAM function VAMRead returned unexpected result: error 600 - 
                            VAM Client Report [mssqlvam::MetadataResolver2K5::InternalGetColumns] Timeout expired Error (-2147217871): Timeout expired
                    

                     

                    There may in fact even be hidden/undocumented settings inside the (sqlserver) database, that allow bypassing the error (i.e., I'm thinking adjusting the timeout).  Usually these errors come from the database, and are only reported by GG.  A lot of GG parameters are just configuring the database session; that sounds like what is needed here.

                    • 7. Re: OGG 11.2.1.0.2 on Win x64 Abends w/o error on VAMRead
                      AntonyLosev

                      Seems that an update from OGG version 11.2.1.0.2 to 11.2.1.0.18 fixed the issue.