So it seems that MM2 is doing a lot of small steps to get the offsets and
consumer groups, am I right?
Maybe this need some optimization or batching. Well I am just guessing
here, I don't really know much about how it works.
Do you have any idea maybe it if can be speed up with configuration?
Thanks,
Peter
On Tue, 24 Mar 2020 at 16:14, Péter Sinóros-Szabó <
peter.sinoros-sz...@transferwise.com> wrote:
> Hey,
>
> so I turned on debug logging and now I see the MM2 does a lot, so it is
> hard to tell exactly what :D
>
> So, what I see the most during that "not mirroring messages" period is
> logs about:
> - [AdminClient clientId=adminclient-31] Queueing
> Call(callName=findCoordinator, deadlineMs=1584976266682) with a timeout
> 120000 ms from now.
> - [AdminClient clientId=adminclient-31] Queueing
> Call(callName=listConsumerGroupOffsets, deadlineMs=1584976267162) with a
> timeout 119999 ms from now.
> - [AdminClient clientId=adminclient-31] Using older server API v1 to send
> FIND_COORDINATOR {key=aaaaabdd997ddhfb8d,key_type=0} with correlation id
> 1473 to node 1004 (org.apache.kafka.clients.NetworkClient)
> - [AdminClient clientId=adminclient-31] Using older server API v3 to send
> OFFSET_FETCH {group_id=vvvvvvvvvv586499b754vctp8,topics=null} with
> correlation id 1062 to node 1006
> - [Consumer clientId=consumer-19, groupId=null] Added READ_UNCOMMITTED
> fetch request for partition mm2-offset-syncs.backup.internal-0 at position
> FetchPosition{offset=5187531, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch ...
> - [Consumer clientId=consumer-19, groupId=null] Sending READ_UNCOMMITTED
> IncrementalFetchRequest(toSend=(), toForget=(),
> implied=(mm2-offset-syncs.backup.internal-0)) to broker ...
> - [Consumer clientId=consumer-19, groupId=null] Using older server API v7
> to send FETCH
> {replica_id=-1,max_wait_time=500,min_bytes=1,max_bytes=52428800, ...
> - [Consumer clientId=consumer-21, groupId=null] Sending READ_UNCOMMITTED
> IncrementalFetchRequest(toSend=(), toForget=(),
> implied=(mm2-offset-syncs.backup.internal-0)) to broker 172.x.y.z:9092 (id:
> 1004 ...
>
> I can share the full log if that helps.
>
> Peter
>
> On Fri, 20 Mar 2020 at 17:52, Ryanne Dolan <ryannedo...@gmail.com> wrote:
>
>> Hmm, maybe turn on debugging info and try to figure out what Connect is
>> doing during that time.
>>
>> Ryanne
>>
>> On Fri, Mar 20, 2020 at 6:15 AM Péter Sinóros-Szabó
>> <peter.sinoros-sz...@transferwise.com.invalid> wrote:
>>
>> > Hi,
>> >
>> > I don't have the previous logs, so I restarted MM2, that produces the
>> same
>> > results. So new logs:
>> >
>> > MM2 starts and seems to be ready, but not mirroring message:
>> > [2020-03-20 10:50:11,985] INFO [Producer
>> > clientId=connector-producer-MirrorCheckpointConnector-0] Cluster ID:
>> > 700ZEsu0ShuzPZ6lZE54_Q (org.apache.kafka.clients.Metadata)
>> > [2020-03-20 10:50:19,927] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> >
>> > It takes another 5 minutes of just the usually "committing offsets"
>> kinda
>> > messages (these are all the logs MM2 prints at that time)
>> > [2020-03-20 10:50:19,927] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:19,927] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:19,936] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 9 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,634] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,635] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,639] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,639] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:50:57,650] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 11 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,887] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:11,887] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:19,936] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:19,936] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:19,941] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,635] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,635] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,651] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,651] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:51:57,658] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 7 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,886] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,933] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
>> > successfully in 47 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,933] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,933] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,965] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
>> > successfully in 32 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,965] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,965] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,997] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
>> > successfully in 32 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,997] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:11,997] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:12,026] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
>> > successfully in 29 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:19,941] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:19,941] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:19,946] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,635] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,635] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,658] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,658] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:52:57,666] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 8 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:11,933] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:11,933] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:11,988] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
>> > successfully in 55 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:11,988] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:11,988] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,027] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
>> > successfully in 39 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,027] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,027] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
>> > successfully in 40 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:12,102] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
>> > successfully in 35 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:19,946] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:19,946] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:19,950] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,667] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,667] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:53:57,682] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 15 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:11,988] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:11,988] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,036] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
>> > successfully in 48 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,036] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,036] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
>> > successfully in 31 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,067] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,101] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
>> > successfully in 34 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,102] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,102] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:12,134] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
>> > successfully in 32 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:19,951] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:19,951] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:19,955] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 4 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,636] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-1}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,637] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-2}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,638] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-0}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,639] INFO
>> WorkerSourceTask{id=MirrorSourceConnector-3}
>> > flushing 0 outstanding messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,682] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,682] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:54:57,690] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 8 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,036] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,036] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,068] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-1} Finished commitOffsets
>> > successfully in 32 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,068] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,068] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,099] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-2} Finished commitOffsets
>> > successfully in 31 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,102] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,102] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,138] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished commitOffsets
>> > successfully in 36 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,138] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,138] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:12,169] INFO
>> > WorkerSourceTask{id=MirrorCheckpointConnector-0} Finished commitOffsets
>> > successfully in 31 ms
>> (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:19,955] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Committing offsets
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:19,955] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} flushing 0 outstanding
>> > messages for offset commit
>> > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:19,960] INFO
>> > WorkerSourceTask{id=MirrorHeartbeatConnector-0} Finished commitOffsets
>> > successfully in 5 ms (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > [2020-03-20 10:55:31,729] INFO [Consumer clientId=consumer-14,
>> > groupId=null] Subscribed to partition(s): ...
>> >
>> >
>> >
>> > and then subscribes to the topics and starts to mirror message:
>> > [2020-03-20 10:55:31,729] INFO [Consumer clientId=consumer-14,
>> > groupId=null] Subscribed to partition(s): ...
>> > [2020-03-20 10:55:31,731] INFO Starting with 303 previously uncommitted
>> > partitions. (org.apache.kafka.connect.mirror.MirrorSourceTask)
>> > [2020-03-20 10:55:31,732] INFO [Consumer clientId=consumer-14,
>> > groupId=null] Seeking to offset 180324042 for partition ...
>> >
>> > There isn't any logs with "x took too long (y ms)" or "timed out running
>> > task x"?
>> > Only some "x took y ms", but all of them during the startup and it does
>> not
>> > seem to be a reason for the 5 minute delay:
>> >
>> >
>> > [2020-03-20 10:49:13,980] INFO Reflections took 1443 ms to scan 92 urls,
>> > producing 4486 keys and 18097 values [using 2 cores]
>> > (org.reflections.Reflections)
>> > [2020-03-20 10:49:14,986] INFO Reflections took 653 ms to scan 92 urls,
>> > producing 4486 keys and 18097 values [using 2 cores]
>> > (org.reflections.Reflections)
>> > [2020-03-20 10:49:16,059] INFO Reflections took 618 ms to scan 92 urls,
>> > producing 4486 keys and 18097 values [using 2 cores]
>> > (org.reflections.Reflections)
>> > [2020-03-20 10:49:19,929] INFO creating internal topics took 13 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:20,997] INFO creating internal topics took 10 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,637] INFO creating internal topics took 21 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,658] INFO creating upstream offset-syncs topic
>> took 29
>> > ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,658] INFO creating internal topics took 33 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,680] INFO loading initial consumer groups took 21
>> ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,953] INFO loading initial set of topic-partitions
>> took
>> > 295 ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,964] INFO creating downstream topic-partitions
>> took 10
>> > ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,980] INFO refreshing known target topics took 15 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:49:57,981] INFO Starting MirrorSourceConnector took 367
>> ms.
>> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
>> > [2020-03-20 10:49:58,442] INFO syncing topic configs took 461 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,316] INFO Stopping MirrorSourceConnector took 6051
>> ms.
>> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
>> > [2020-03-20 10:50:07,329] INFO creating upstream offset-syncs topic
>> took 9
>> > ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,395] INFO loading initial set of topic-partitions
>> took
>> > 66 ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,397] INFO creating downstream topic-partitions
>> took 2
>> > ms (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,412] INFO refreshing known target topics took 15 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,412] INFO Starting MirrorSourceConnector took 95
>> ms.
>> > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
>> > [2020-03-20 10:50:07,430] INFO creating internal topics took 13 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,448] INFO creating internal topics took 13 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,457] INFO loading initial consumer groups took 8 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:07,844] INFO syncing topic configs took 432 ms
>> > (org.apache.kafka.connect.mirror.Scheduler)
>> > [2020-03-20 10:50:09,755] INFO Stopping DistributedHerder-connect-1 took
>> > 922 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:10,749] INFO Stopping DistributedHerder-connect-1 took
>> > 994 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:10,755] INFO Stopping DistributedHerder-connect-1
>> took 6
>> > ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:11,749] INFO Stopping DistributedHerder-connect-1 took
>> > 994 ms. (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:11,859] INFO Stopping
>> > task-thread-MirrorCheckpointConnector-3 took 3 ms.
>> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:11,861] INFO Stopping
>> > task-thread-MirrorCheckpointConnector-2 took 7 ms.
>> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:11,861] INFO Stopping
>> > task-thread-MirrorCheckpointConnector-0 took 5 ms.
>> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> > [2020-03-20 10:50:11,862] INFO Stopping
>> > task-thread-MirrorCheckpointConnector-1 took 6 ms.
>> > (org.apache.kafka.connect.mirror.MirrorCheckpointTask)
>> >
>> >
>> >
>> >
>> > Peter
>> >
>> > On Wed, 18 Mar 2020 at 15:12, Ryanne Dolan <ryannedo...@gmail.com>
>> wrote:
>> >
>> > > Peter, can you share any log lines like "x took y ms" or "x took too
>> long
>> > > (y ms)" or "timed out running task x"?
>> > >
>> > > Ryanne
>> > >
>> > > On Tue, Mar 17, 2020 at 10:45 AM Péter Sinóros-Szabó
>> > > <peter.sinoros-sz...@transferwise.com.invalid> wrote:
>> > >
>> > > > Hey,
>> > > >
>> > > > Running a MM2 cluster to mirror from A->B clusters I noticed that
>> when
>> > I
>> > > > add a new topic to A cluster, MM2 will notice it:
>> > > > [2020-03-17 13:14:05,477] INFO Found 2719 topic-partitions on main.
>> 1
>> > are
>> > > > new. 0 were removed. Previously had 2718.
>> > > > (org.apache.kafka.connect.mirror.MirrorSourceConnector)
>> > > >
>> > > > That's fine. It seems that MM2 connectors just simply restart to
>> start
>> > up
>> > > > with the new configuration.
>> > > > My problem is that it takes about 5 minutes for MM2 to start to
>> mirror
>> > > > messages again.
>> > > >
>> > > > What I see in the logs are:
>> > > > [2020-03-17 13:14:07,107] INFO Kafka startTimeMs: 1584450847106
>> > > > (org.apache.kafka.common.utils.AppInfoParser)
>> > > > [2020-03-17 13:14:07,204] INFO [Producer clientId=producer-11]
>> Cluster
>> > > ID:
>> > > > wif2mnkZTayzAEOb2VyoLA (org.apache.kafka.clients.Metadata)
>> > > >
>> > > > It seems that MM2 restarts the connectors in 2 seconds.
>> > > > But then I see the usual logs, but according to MM2's metrics, it is
>> > not
>> > > > mirroring any messages for about 5 minutes.
>> > > >
>> > > > [2020-03-17 13:14:10,485] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > > [2020-03-17 13:14:10,485] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Committing offsets
>> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > > [2020-03-17 13:14:10,485] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0
>> outstanding
>> > > > messages for offset commit
>> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > > [2020-03-17 13:14:10,485] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} flushing 0
>> outstanding
>> > > > messages for offset commit
>> > > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > > [2020-03-17 13:14:10,637] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished
>> commitOffsets
>> > > > successfully in 152 ms
>> > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > > [2020-03-17 13:14:10,637] INFO
>> > > > WorkerSourceTask{id=MirrorCheckpointConnector-3} Finished
>> commitOffsets
>> > > > successfully in 152 ms
>> > > (org.apache.kafka.connect.runtime.WorkerSourceTask)
>> > > >
>> > > > So after ~5 minutes, I see that it is subscribing to the topics...
>> and
>> > I
>> > > > also see in the metrics that that is the time when it starts to
>> mirror
>> > > > messages.
>> > > >
>> > > > [2020-03-17 13:19:39,850] INFO [Consumer clientId=consumer-39,
>> > > > groupId=null] Subscribed to partition(s): ...
>> > > > [2020-03-17 13:19:39,851] INFO Starting with 308 previously
>> uncommitted
>> > > > partitions. (org.apache.kafka.connect.mirror.MirrorSourceTask)
>> > > > [2020-03-17 13:19:39,851] INFO [Consumer clientId=consumer-39,
>> > > > groupId=null] Seeking to offset 178508243 for partition
>> > > > twTasks.austrac-service.executeTask.default-0 (org.apache.kafka
>> > > >
>> > > >
>> > > > Is there any idea how to speed this up?
>> > > >
>> > > > Thanks,
>> > > > Peter
>> > > >
>> > >
>> >
>>
>
