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 from
source 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 5980711583219
T16: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
