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

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)