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

Oracle12С XStream. Sometimes CPU utilization of DBZ is very low.

    XMLWordPrintable

Details

    Description

      We are testing  the oracle connector version 1.4 in distributed mode of kafka connect.

      One of our tests is inserts in two tables with the commit every 100 records. The duration of inserts is 30 minutes. The structure of tables is in attach tables.sql.

      Below results of our test were on December 29 2021 (start at 15:52).

      The attach CPU_utilization_DB_DBZ.png is CPU of Oracle DB's server - left side and CPU of DBZ's server - right one.

      The attach CPU_utilization_DBZ_phases.png is phases of working process DBZ server.

      Look at phase 1 and 2. They are so strange. DBZ does nothing at these moments.

       

      The logs details:

      Snapshot was created

       ...............

      [2020-12-29 15:45:53,458] INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'APPLY_DT' (io.debezium.connector.oracle.OracleValueConverters:89)

      [2020-12-29 15:45:53,478] INFO Snapshot step 7 - Skipping snapshotting of data (io.debezium.relational.RelationalSnapshotChangeEventSource:141)

      [2020-12-29 15:45:53,480] INFO Snapshot - Final stage (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource:83)

      [2020-12-29 15:45:53,480] INFO Snapshot ended with SnapshotResult [status=COMPLETED, offset=OracleOffsetContext [scn=197354460]] (io.debezium.pipeline.ChangeEventSourceCoordinator:106)

      [2020-12-29 15:45:53,480] INFO Snapshot ended with SnapshotResult [status=COMPLETED, offset=OracleOffsetContext [scn=197354460]] (io.debezium.pipeline.ChangeEventSourceCoordinator:106)

      [2020-12-29 15:45:53,482] INFO Connected metrics set to 'true' (io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics:60)

      [2020-12-29 15:45:53,482] INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator:139)

      [2020-12-29 15:45:53,482] INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator:139)

      [2020-12-29 15:45:54,408] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      .......... 

      Start inserts at 15:52

       .........

      [2020-12-29 15:52:12,446] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 15:52:12,447] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 15:53:55,586] INFO The task will send records to topic 'orcl12.XEN.ACCOUNT' for the first time. Checking whether topic exists (org.apache.kafka.connect.runtime.WorkerSourceTask:414)

      [2020-12-29 15:53:55,590] INFO Topic 'orcl12.XEN.ACCOUNT' already exists. (org.apache.kafka.connect.runtime.WorkerSourceTask:418)

      [2020-12-29 15:53:56,504] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 15:53:56,504] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 25 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 15:53:56,512] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 8 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 15:53:58,309] INFO The task will send records to topic 'orcl12.XEN.ACNT_CONTRACT' for the first time. Checking whether topic exists (org.apache.kafka.connect.runtime.WorkerSourceTask:414)

      [2020-12-29 15:53:58,314] INFO Topic 'orcl12.XEN.ACNT_CONTRACT' already exists. (org.apache.kafka.connect.runtime.WorkerSourceTask:418)

      [2020-12-29 15:54:02,616] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 15:54:02,616] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 564 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

       .......

      Phase 0. DBZ was working. Attention to time 16:03

       ......

      [2020-12-29 15:54:02,616] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 564 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 15:54:02,736] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 120 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 15:55:07,669] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 15:55:07,669] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 2130 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 15:55:07,999] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 330 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 15:55:53,147] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      ......................................................................

      [2020-12-29 16:02:29,406] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 7210 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:02:29,669] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 263 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 16:03:01,406] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:03:01,406] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:03:01,410] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 16:03:31,656] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:03:31,656] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

       

      Phase 1. DBZ was doing nothing

       

      [2020-12-29 16:03:01,406] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:03:01,410] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 16:03:31,656] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:03:31,656] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      .................

      [2020-12-29 16:15:12,003] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:15:21,908] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:15:21,908] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

       

       Between phase 1 and 2 you can see a hill of CPU

       

      [2020-12-29 16:15:52,303] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:15:52,303] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:17:23,101] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:17:23,101] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 4132 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:17:23,243] INFO WorkerSourceTask{id=debizium-connector-12-0} Finished commitOffsets successfully in 142 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:574)

      [2020-12-29 16:17:46,217] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:17:46,217] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

       

      Phase 3. CPU utilization of DBZ increased.

       

      [2020-12-29 16:20:58,275] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      [2020-12-29 16:23:00,376] INFO WorkerSourceTask{id=debizium-connector-12-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:478)

      [2020-12-29 16:23:00,376] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 1674 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

      ....................

      [2020-12-29 16:31:41,989] INFO WorkerSourceTask{id=debizium-connector-12-0} flushing 602 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:495)

       

       

      Attachments

        1. all.PNG
          all.PNG
          115 kB
        2. all-1.PNG
          all-1.PNG
          115 kB
        3. connect.log.2020-12-29-15
          201 kB
        4. connect.log.2020-12-29-16
          26 kB
        5. CPU_utilization_DB_DBZ.png
          CPU_utilization_DB_DBZ.png
          44 kB
        6. CPU_utilization_DBZ_20201230.png
          CPU_utilization_DBZ_20201230.png
          106 kB
        7. CPU_utilization_DBZ_20201230-1.png
          CPU_utilization_DBZ_20201230-1.png
          106 kB
        8. CPU_utilization_DBZ_phases.png
          CPU_utilization_DBZ_phases.png
          31 kB
        9. db_cpu.PNG
          db_cpu.PNG
          48 kB
        10. db_cpu-1.PNG
          db_cpu-1.PNG
          48 kB
        11. dbz_cpu.PNG
          dbz_cpu.PNG
          53 kB
        12. dbz_cpu-1.PNG
          dbz_cpu-1.PNG
          53 kB
        13. dbz_queues.PNG
          dbz_queues.PNG
          51 kB
        14. dbz_queues-1.PNG
          dbz_queues-1.PNG
          51 kB
        15. tables.sql
          8 kB

        Issue Links

          Activity

            People

              ccranfor@redhat.com Chris Cranford
              ctuluctulu@gmail.com Andrey Sevostyanov (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: