Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-4342

Oracle connector - 105 minute delay to receiving update

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Obsolete
    • Icon: Major Major
    • None
    • 1.8.0.Alpha2
    • oracle-connector
    • None
    • False
    • False

      I was expecting debezium to receive oracle changes (ie updated rows) within 10minutes but it took 105minutes for a single update to arrive. I couldn't see anything in the FAQ about debugging/tuning this.

       

      my configs (standalone mode):

      name=oracle-source
      connector.class=io.debezium.connector.oracle.OracleConnector
      tasks.max=1
      message.key.columns=(.*).(.*):(.*)
      database.server.name=my-topicoracle
      database.user=redact
      database.password=redact
      database.url=jdbc:oracle:thin:@(DESCRIPTION=(ADDRESS_LIST=(LOAD_BALANCE=YES)(FAILOVER=YES)(ADDRESS=(PROTOCOL=tcp)(HOST=redact)(PORT=redact)))(CONNECT_DATA=(SERVICE_NAME=redact1)))?oracle.net.disableOob=true
      database.dbname=redact1
      database.pdb.name=red
      table.include.list=a.b
      database.history.kafka.bootstrap.servers=redact
      topic.creation.enable=true
      topic.creation.default.replication.factor=3
      topic.creation.default.partitions=12
      decimal.handling.mode=string
      transforms=unwrap
      transforms.unwrap.type=io.debezium.transforms.ExtractNewRecordState
      transforms.unwrap.drop.tombstones=false
      transforms.unwrap.delete.handling.mode=rewrite
      transforms.unwrap.add.fields=scn,op,source.ts_ms:source_ts_ms,ts_ms
      bootstrap.servers=redact
      key.converter=io.confluent.connect.avro.AvroConverter
      key.converter.schema.registry.url=http://localhost:8081
      value.converter=io.confluent.connect.avro.AvroConverter
      value.converter.schema.registry.url=http://localhost:8081
      producer.compression.type=gzip
      offset.storage.file.filename=/tmp/connect.offsets
      offset.flush.interval.ms=10000
      offset.flush.timeout.ms=60000
      plugin.path=/home/user/opt/kafka_2.12-2.8.1/connectors/confluentinc-kafka-connect-jdbc-10.2.5/lib
      consumer.group.id=my-group
       

      i updated 1 record (just changing a single column's value from N to N/A) in the oracle db (version 19c) at 07:35. Apart from that 1 rupdate, there is no other DML/DDL activity happening on the oracle db at all, just select queries. my table has no PK

       

      logs:

      [2021-11-22 07:32:10,292] INFO Kafka version: 2.8.1 (org.apache.kafka.common.utils.AppInfoParser:119)
      [2021-11-22 07:32:10,292] INFO Kafka commitId: 83red (org.apache.kafka.common.utils.AppInfoParser:120)
      [2021-11-22 07:32:10,292] INFO Kafka startTimeMs: 1637566330292 (org.apache.kafka.common.utils.AppInfoParser:121)
      [2021-11-22 07:32:10,341] INFO [Consumer clientId=my-topicoracle-dbhistory, groupId=my-topicoracle-dbhistory] Cluster ID: mee (org.apache.kafka.clients.Metadata:279)
      [2021-11-22 07:32:12,090] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics:659)
      [2021-11-22 07:32:12,090] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics:663)
      [2021-11-22 07:32:12,090] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics:669)
      [2021-11-22 07:32:12,091] INFO App info kafka.consumer for my-topicoracle-dbhistory unregistered (org.apache.kafka.common.utils.AppInfoParser:83)
      [2021-11-22 07:32:12,102] INFO Requested thread factory for connector OracleConnector, id = my-topicoracle named = change-event-source-coordinator (io.debezium.util.Threads:270)
      [2021-11-22 07:32:12,103] INFO Creating thread debezium-oracleconnector-my-topicoracle-change-event-source-coordinator (io.debezium.util.Threads:287)
      [2021-11-22 07:32:12,104] INFO WorkerSourceTask{id=oracle-source-0} Source task finished initialization and start (org.apache.kafka.connect.runtime.WorkerSourceTask:232)
      [2021-11-22 07:32:12,104] INFO WorkerSourceTask{id=oracle-source-0} Executing source task (org.apache.kafka.connect.runtime.WorkerSourceTask:238)
      [2021-11-22 07:32:12,106] INFO Metrics registered (io.debezium.pipeline.ChangeEventSourceCoordinator:104)
      [2021-11-22 07:32:12,107] INFO Context created (io.debezium.pipeline.ChangeEventSourceCoordinator:107)
      [2021-11-22 07:32:12,110] INFO No previous offset has been found. (io.debezium.connector.oracle.OracleSnapshotChangeEventSource:67)
      [2021-11-22 07:32:12,110] INFO According to the connector configuration both schema and data will be snapshot. (io.debezium.connector.oracle.OracleSnapshotChangeEventSource:72)
      [2021-11-22 07:32:12,116] INFO Snapshot step 1 - Preparing (io.debezium.relational.RelationalSnapshotChangeEventSource:93)
      [2021-11-22 07:32:12,116] INFO Snapshot step 2 - Determining captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource:102)
      [2021-11-22 07:32:19,999] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 07:32:25,148] INFO Snapshot step 3 - Locking captured tables [redact.a.b] (io.debezium.relational.RelationalSnapshotChangeEventSource:109)
      [2021-11-22 07:32:25,157] INFO Snapshot step 4 - Determining snapshot offset (io.debezium.relational.RelationalSnapshotChangeEventSource:115)
      [2021-11-22 07:32:25,172] INFO No latest table SCN could be resolved, defaulting to current SCN (io.debezium.connector.oracle.OracleSnapshotChangeEventSource:213)
      [2021-11-22 07:32:25,187] INFO Snapshot step 5 - Reading structure of captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource:118)
      [2021-11-22 07:32:26,381] INFO Snapshot step 6 - Persisting schema history (io.debezium.relational.RelationalSnapshotChangeEventSource:122)
      [2021-11-22 07:32:26,890] WARN The Kafka Connect schema name 'my-topicoracle.a.b.Value' is not a valid Avro schema name, so replacing with 'my_topicoracle.a.b.Value' (io.debezium.util.SchemaNameAdjuster:172)
      [2021-11-22 07:32:26,891] WARN The Kafka Connect schema name 'my-topicoracle.a.b.Key' is not a valid Avro schema name, so replacing with 'my_topicoracle.a.b.Key' (io.debezium.util.SchemaNameAdjuster:172)
      [2021-11-22 07:32:26,901] WARN The Kafka Connect schema name 'my-topicoracle.a.b.Envelope' is not a valid Avro schema name, so replacing with 'my_topicoracle.a.b.Envelope' (io.debezium.util.SchemaNameAdjuster:172)
      [2021-11-22 07:32:27,106] INFO Snapshot step 7 - Snapshotting data (io.debezium.relational.RelationalSnapshotChangeEventSource:134)
      [2021-11-22 07:32:27,107] INFO Snapshotting contents of 1 tables while still in transaction (io.debezium.relational.RelationalSnapshotChangeEventSource:304)
      [2021-11-22 07:32:27,107] INFO Exporting data from table 'redact.a.b' (1 of 1 tables) (io.debezium.relational.RelationalSnapshotChangeEventSource:340)
      [2021-11-22 07:32:27,110] INFO   For table 'redact.a.b' using select statement: 'SELECT "ID", "CONTRACT_NUMBER",....redact (it is 140 columns) FROM "a"."b" AS OF SCN 521152477900' (io.debezium.relational.RelationalSnapshotChangeEventSource:348)
      [2021-11-22 07:32:27,136] INFO 1 records sent during previous 00:00:17.278, last recorded offset: {snapshot=true, scn=521152477900, snapshot_completed=false} (io.debezium.connector.common.BaseSourceTask:185)
      [2021-11-22 07:32:27,499] INFO The task will send records to topic 'my-topicoracle' for the first time. Checking whether topic exists (org.apache.kafka.connect.runtime.WorkerSourceTask:424)
      [2021-11-22 07:32:27,597] INFO Topic 'my-topicoracle' already exists. (org.apache.kafka.connect.runtime.WorkerSourceTask:428)
      [2021-11-22 07:32:28,130] INFO The task will send records to topic 'my-topicoracle.a.b' for the first time. Checking whether topic exists (org.apache.kafka.connect.runtime.WorkerSourceTask:424)
      [2021-11-22 07:32:28,141] INFO Topic 'my-topicoracle.a.b' already exists. (org.apache.kafka.connect.runtime.WorkerSourceTask:428)
      [2021-11-22 07:32:30,000] INFO WorkerSourceTask{id=oracle-source-0} flushing 57 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 07:32:37,203] INFO   Exported 64000 records for table 'redact.a.b' after 00:00:10.095 (io.debezium.relational.RelationalSnapshotChangeEventSource:376)
      [2021-11-22 07:32:40,019] INFO WorkerSourceTask{id=oracle-source-0} flushing 332 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 07:32:45,008] INFO 143360 records sent during previous 00:00:17.873, last recorded offset: {snapshot=true, scn=521152477900, snapshot_completed=false} (io.debezium.connector.common.BaseSourceTask:185)
      [2021-11-22 07:32:47,204] INFO   Exported 170306 records for table 'redact.a.b' after 00:00:20.097 (io.debezium.relational.RelationalSnapshotChangeEventSource:376)
      [2021-11-22 07:32:50,076] INFO WorkerSourceTask{id=oracle-source-0} flushing 88 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 07:32:53,114] INFO   Finished exporting 243952 records for table 'redact.a.b'; total duration '00:00:26.007' (io.debezium.relational.RelationalSnapshotChangeEventSource:393)
      [2021-11-22 07:32:53,121] INFO Snapshot - Final stage (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource:83)
      [2021-11-22 07:32:53,143] INFO Snapshot ended with SnapshotResult [status=COMPLETED, offset=OracleOffsetContext [scn=521152477900]] (io.debezium.pipeline.ChangeEventSourceCoordinator:119)
      [2021-11-22 07:32:53,146] INFO Connected metrics set to 'true' (io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics:70)
      [2021-11-22 07:32:53,146] INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator:163)
      [2021-11-22 07:33:00,084] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 07:33:10,085] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      ........
      ........
      ........the logs are just repeated like this here every 20 seconds so did not paste every iteration in this JIRA......
      ........
      ........
      [2021-11-22 09:20:10,315] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 09:20:20,316] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510)
      [2021-11-22 09:20:26,243] INFO 100595 records sent during previous 01:47:41.235, last recorded offset: {commit_scn=521152756892, transaction_id=null, scn=521152731524} (io.debezium.connector.common.BaseSourceTask:185)
      [2021-11-22 09:20:30,316] INFO WorkerSourceTask{id=oracle-source-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:510) 

        1. alertlog.txt
          6.89 MB
          toop toop
        2. image-2021-11-30-09-10-57-550.png
          18 kB
          toop toop

              Unassigned Unassigned
              tooptoop toop toop (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: