GoldenGate extract stuck after change of database COMPATIBLE parameter
Date: Tue, 16 Mar 2021 19:19:48 +0100
Message-ID: <CAHOQdbsL1GW_wF8fgNc45OwHV3=EB7hPtYU8-xSZh1GOspgSbQ_at_mail.gmail.com>
Hi everyone,
I am working on a GoldenGate issue for some days and wondering if you have any ideas on this.
After changing the COMPATIBLE parameter from 11.2.0.4 to 19.0.0 on a recently upgraded database, the GoldenGate integrated EXTRACT stopped working. Looking into the database alert log, I see LOGMINER connecting, reading logs required for recovery and then stopping on a certain archive log file. This particular logfile "o1_mf_1_180314__kr538skt_.arc" where logminer is stuck was generated after the database was restarted with the 19c compatible parameter.
GoldenGate version is 19.1.0.0.0 (with patch 31908556 applied) and source database version is 19.9.
Extract report:
18:01:03 INFO OGG-02339 Integrated capture successfully attached to logmining server OGG$EXTRACT_NAME_REDACTED using 60 second streaming duration.
18:01:03 INFO OGG-02089 Source redo compatibility version is: 19.0.0. 18:01:03 INFO OGG-02086 Integrated Dictionary will be used. 18:01:03 INFO OGG-02710 Database metadata information is obtained fromsource database.
18:01:03 WARNING OGG-02905 Replication of OID column in object tables may diverge.
18:01:03 INFO OGG-02776 Native data capture is enabled for Oracle NUMBER data type.
18:01:03 INFO OGG-01971 The previous message, 'INFO OGG-02776', repeated 1 times.
18:01:03 INFO OGG-01055 Recovery initialization completed for target file /PATH_REDACTED/ON062807, at RBA 1409. 18:01:03 INFO OGG-01478 Output file /PATH_REDACTED/ON is using format RELEASE 19.1.
18:01:03 INFO OGG-02776 Native data capture is enabled for Oracle NUMBER data type.
18:01:03 INFO OGG-01026 Rolling over remote file
/PATH_REDACTED/ON062807.
18:01:03 INFO OGG-01053 Recovery completed for target file
/PATH_REDACTED/ON062808, at RBA 1419.
18:01:03 INFO OGG-01057 Recovery completed for all targets.
- Run Time Messages **
18:30:28 WARNING OGG-01027 Long Running Transaction: XID 0.66.3.7570345, Items 0, Extract EXTRACT_NAME_REDACTED, Redo Thread 2, SCN 1890.1269635699 (8118757825139), Redo Seq #174998, Redo RBA 1638495884.
Database instance alert.log:
Starting persistent Logminer Session with sid = 387 for GoldenGate Capture OGG$EXTRACT_NAME_REDACTED (OS id=112641).
LOGMINER: Parameters summary for session# = 387 LOGMINER: Number of processes = 3, Transaction Chunk Size = 1 LOGMINER: Memory Size = 199M, Checkpoint interval = 1000M LOGMINER: SpillScn 0, ResetLogScn 5980711583219T16:12:57.197490+01:00
LOGMINER: summary for session# = 387 LOGMINER: StartScn: 8118757825138 (0x000007624bad1a72) LOGMINER: EndScn: 0 LOGMINER: HighConsumedScn: 8118757825138 (0x000007624bad1a72) LOGMINER: PSR flags: 0x4f0 LOGMINER: Session Flags: 0x3fe8c2d0 LOGMINER: Session Flags2: 0x901c3 LOGMINER: RECOVERY_ROLLBACK PDML grouping is on LOGMINER: DDL CKPT is on LOGMINER: Read buffers: 256 LOGMINER: Region Queue size: 4096 LOGMINER: Redo Queue size: 65536 LOGMINER: Memory Size = 199M, HWM 189M, LWM 159M, 79% LOGMINER: Memory Release Limit: 1M LOGMINER: Max Decomp Region Memory: 1M LOGMINER: Transaction Queue Size: 131072 LOGMINER: lowCkptScn: 8118757825138 (0x000007624bad1a72) LOGMINER: highCkptScn: 0 (0x0000000000000000) LOGMINER: SkipScn: 8118757825138 (0x000007624bad1a72)T16:12:57.497253+01:00
LOGMINER: session#=387 (OGG$EXTRACT_NAME_REDACTED), merger LX00 pid=107 OS id=112692 sid=3124 started
T16:12:57.522601+01:00
LOGMINER: session#=387 (OGG$EXTRACT_NAME_REDACTED), builder MS00 pid=109 OS id=112694 sid=3690 started
T16:12:57.545206+01:00
LOGMINER: session#=387 (OGG$EXTRACT_NAME_REDACTED), preparer MS01 pid=112 OS id=112696 sid=13 started
T16:12:57.690625+01:00
T16:12:57.691707+01:00
Initializing RBA broadcast for log mining
OGG Capture client successfully attached to GoldenGate Capture
OGG$EXTRACT_NAME_REDACTED to receive uncommitted changes with pid=70 OS
id=112641.
T16:12:57.699328+01:00
GoldenGate OGG$EXTRACT_NAME_REDACTED Capture sends LCRs using streaming
mode (OCI call duration=60 secs, bufsize=1024000).
T16:12:57.719430+01:00
LOGMINER: session#=387 (OGG$EXTRACT_NAME_REDACTED), reader H001 pid=114 OS
id=112698 sid=581 started
T16:12:57.741368+01:00
LOGMINER: session#=387 (OGG$EXTRACT_NAME_REDACTED), reader H002 pid=115 OS
id=112701 sid=865 started
T16:12:57.793793+01:00
LOGMINER: Begin mining logfile for session 387 thread 1 sequence 180312,
/PATH_REDACTED/o1_mf_1_180312__kr1z3f0v_.arc
T16:12:57.805949+01:00
LOGMINER: Begin mining logfile for session 387 thread 2 sequence 174998,
/PATH_REDACTED/o1_mf_2_174998__kr1vbxnk_.arc
T16:12:57.850098+01:00
LOGMINER: End mining logfile for session 387 thread 1 sequence 180312,
/PATH_REDACTED/o1_mf_1_180312__kr1z3f0v_.arc
T16:12:58.019440+01:00
LOGMINER: Begin mining logfile for session 387 thread 1 sequence 180313,
/PATH_REDACTED/o1_mf_1_180313__kr52rrh5_.arc
T16:12:58.021625+01:00
LOGMINER: End mining logfile for session 387 thread 1 sequence 180313,
/PATH_REDACTED/o1_mf_1_180313__kr52rrh5_.arc
T16:12:58.165555+01:00
LOGMINER: Begin mining logfile for session 387 thread 1 sequence 180314,
/PATH_REDACTED/o1_mf_1_180314__kr538skt_.arc
T16:13:01.001518+01:00
LogMnr ktu_gtx_print: malformed redo!
T16:13:01.016880+01:00
LogMnr ktu_gtx_print: malformed redo!
Starting from the LogMnr message I did find support note "Alert.log Warning - LogMnr Ktu_gtx_print: Malformed Redo! (Doc ID 2593142.1)" but there is no ORA-xxxx assert happening along side this warning.
The file o1_mf_1_180314__kr538skt_.arc is 1KB in size but I do not know if this is relevant, as the previous one, o1_mf_1_180312__kr1z3f0v_.arc, is also 1KB and LOGMINER moves on. Using dbms_logmnr and alter system dump logfile work on o1_mf_1_180314__kr538skt_.arc but for some reason logminer does not go to the End of this particular logfile.
Thank you,
Andrei
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Mar 16 2021 - 19:19:48 CET