You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Steve Jones <jo...@gmail.com> on 2020/09/02 18:52:12 UTC
Re: Streams constantly reblancing,
Just an addition to this in case someone can help, I'm seeing zero thread
activity in the rebalancing but I'm also not seeing anything being logged
by Kafka to indicate its doing anything on rebalancing (Logging level set
to ALL), producer and consumer code works fine but streams just appears to
hang.
On Mon, 31 Aug 2020 at 12:49, Steve Jones <jo...@gmail.com> wrote:
> When running an application on the Mac it works fine, when running exactly
> the same app and config on the Raspberry Pi it constantly says it is
> "Rebalancing" the streams
>
> 2020-08-31 12:47:11 INFO
> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka version:
> 2.6.0
>
> ''2020-08-31 12:47:11 INFO
> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka commitId:
> 62abe01bee039651
>
> ''2020-08-31 12:47:11 INFO
> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> startTimeMs: 1598903231499
>
> ''2020-08-31 12:47:11 WARNING org.apache.kafka.streams.StreamsConfig
> checkIfUnexpectedUserSpecifiedConsumerConfig Unexpected user-specified
> consumer config: enable.auto.commit found. User setting (true) will be
> ignored and the Streams default setting (false) will be used
>
> ''2020-08-31 12:47:11 INFO org.apache.kafka.streams.KafkaStreams setState
> stream-client [pi-test-84721b40-dfa1-4848-b3de-5c7561048403] State
> transition from CREATED to REBALANCING
>
> ''2020-08-31 12:47:11 INFO
> com.businesssoa.home.events.filter.dispatcher.kafka.SensorPipe start Pipe
> STARTED
>
> ''2020-08-31 12:47:11 INFO
> org.apache.kafka.streams.processor.internals.StreamThread run stream-thread
> [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1] Starting
>
> ''2020-08-31 12:47:11 INFO
> org.apache.kafka.streams.processor.internals.StreamThread setState
> stream-thread [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1]
> State transition from CREATED to STARTING
>
> ''2020-08-31 12:47:11 INFO org.apache.kafka.clients.consumer.KafkaConsumer
> subscribe [Consumer
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> groupId=pi-test] Subscribed to topic(s): filtered-topic, reading-topic
>
> ''2020-08-31 12:47:11 INFO com.businesssoa.home.events.filter.App
> waitTillStarted Status is REBALANCING , 1
>
> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> [Producer
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-producer]
> Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
>
> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> [Consumer
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> groupId=pi-test] Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
>
> ''2020-08-31 12:47:41 INFO com.businesssoa.home.events.filter.App
> waitTillStarted Status is REBALANCING , 2
>
> ''2020-08-31 12:48:11 INFO com.businesssoa.home.events.filter.App
> waitTillStarted Status is REBALANCING , 3
>
> Any guidance on how I can debug the streams as to why its constantly
> rebalancing?
>
> Steve
>
>
Re: Streams constantly reblancing,
Posted by Sophie Blee-Goldman <so...@confluent.io>.
That definitely sounds pretty odd if no new logs are showing up on the
Streams side. This is just a guess, but is there any chance the source
topics aren't being found during startup? I was just reminded of a bug in
an old-ish version where Streams would gracefully shutdown but remain
in the REBALANCING state when it couldn't detect the source topics.
What version are you using?
On Thu, Sep 3, 2020 at 8:11 AM Steve Jones <jo...@gmail.com> wrote:
> There are zero events on the stream in the case with the log files, I've
> had the same behaviour when running with 6 events. Its constantly
> reporting rebalancing but from a CPU perspective nothing appears to
> actually be doing anything.
>
> I've run it for several hours just to see if something happened (checking
> every 30 seconds) and there are no log events from Kafka during those
> times. So the log file (filter.log) shows the logs for about an hour and a
> quarter run, my confusion comes from the fact that looking via JMX and at
> the CPU logs it appears that nothing much is actually being done on the
> Kafka side but there aren't any exceptions.
>
> Help and hints appreciated.
>
> Steve
>
> On Wed, 2 Sep 2020 at 12:27, Sophie Blee-Goldman <so...@confluent.io>
> wrote:
>
> > Hey steve,
> >
> > I guess the first question I have is, is the consumer group actually
> > rebalancing
> > or does KafkaStreams just appear to be "stuck" in the REBALANCING state?
> If
> > this application has been run before and there is a large amount of data
> in
> > the
> > changelog topics, it might take a while to rebuild the local state stores
> > from the
> > changelog. During this time it would appear to be in REBALANCING, but
> it's
> > actually
> > just restoring.
> >
> > Just one possibility of many. How long did you let it run without seeing
> it
> > stabilize?
> > It's difficult to diagnose from just the small snippet of logs above, so
> I
> > would
> > try and take a look at the full picture over more than just a minute.
> There
> > *should*
> > be something slightly more helpful logged if it really is stuck in a
> cycle
> > of endless
> > rebalances (eg timing out on the session interval)
> >
> > On Wed, Sep 2, 2020 at 11:52 AM Steve Jones <jo...@gmail.com>
> > wrote:
> >
> > > Just an addition to this in case someone can help, I'm seeing zero
> thread
> > > activity in the rebalancing but I'm also not seeing anything being
> logged
> > > by Kafka to indicate its doing anything on rebalancing (Logging level
> set
> > > to ALL), producer and consumer code works fine but streams just appears
> > to
> > > hang.
> > >
> > > On Mon, 31 Aug 2020 at 12:49, Steve Jones <jo...@gmail.com>
> > wrote:
> > >
> > >> When running an application on the Mac it works fine, when running
> > >> exactly the same app and config on the Raspberry Pi it constantly says
> > it
> > >> is "Rebalancing" the streams
> > >>
> > >> 2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> > version:
> > >> 2.6.0
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> > commitId:
> > >> 62abe01bee039651
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> > >> startTimeMs: 1598903231499
> > >>
> > >> ''2020-08-31 12:47:11 WARNING org.apache.kafka.streams.StreamsConfig
> > >> checkIfUnexpectedUserSpecifiedConsumerConfig Unexpected user-specified
> > >> consumer config: enable.auto.commit found. User setting (true) will be
> > >> ignored and the Streams default setting (false) will be used
> > >>
> > >> ''2020-08-31 12:47:11 INFO org.apache.kafka.streams.KafkaStreams
> > setState
> > >> stream-client [pi-test-84721b40-dfa1-4848-b3de-5c7561048403] State
> > >> transition from CREATED to REBALANCING
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> com.businesssoa.home.events.filter.dispatcher.kafka.SensorPipe start
> > Pipe
> > >> STARTED
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.streams.processor.internals.StreamThread run
> > stream-thread
> > >> [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1] Starting
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.streams.processor.internals.StreamThread setState
> > >> stream-thread
> > [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1]
> > >> State transition from CREATED to STARTING
> > >>
> > >> ''2020-08-31 12:47:11 INFO
> > >> org.apache.kafka.clients.consumer.KafkaConsumer subscribe [Consumer
> > >>
> >
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> > >> groupId=pi-test] Subscribed to topic(s): filtered-topic, reading-topic
> > >>
> > >> ''2020-08-31 12:47:11 INFO com.businesssoa.home.events.filter.App
> > >> waitTillStarted Status is REBALANCING , 1
> > >>
> > >> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> > >> [Producer
> > >>
> >
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-producer]
> > >> Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
> > >>
> > >> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> > >> [Consumer
> > >>
> >
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> > >> groupId=pi-test] Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
> > >>
> > >> ''2020-08-31 12:47:41 INFO com.businesssoa.home.events.filter.App
> > >> waitTillStarted Status is REBALANCING , 2
> > >>
> > >> ''2020-08-31 12:48:11 INFO com.businesssoa.home.events.filter.App
> > >> waitTillStarted Status is REBALANCING , 3
> > >>
> > >> Any guidance on how I can debug the streams as to why its constantly
> > >> rebalancing?
> > >>
> > >> Steve
> > >>
> > >>
> >
>
Re: Streams constantly reblancing,
Posted by Steve Jones <jo...@gmail.com>.
There are zero events on the stream in the case with the log files, I've
had the same behaviour when running with 6 events. Its constantly
reporting rebalancing but from a CPU perspective nothing appears to
actually be doing anything.
I've run it for several hours just to see if something happened (checking
every 30 seconds) and there are no log events from Kafka during those
times. So the log file (filter.log) shows the logs for about an hour and a
quarter run, my confusion comes from the fact that looking via JMX and at
the CPU logs it appears that nothing much is actually being done on the
Kafka side but there aren't any exceptions.
Help and hints appreciated.
Steve
On Wed, 2 Sep 2020 at 12:27, Sophie Blee-Goldman <so...@confluent.io>
wrote:
> Hey steve,
>
> I guess the first question I have is, is the consumer group actually
> rebalancing
> or does KafkaStreams just appear to be "stuck" in the REBALANCING state? If
> this application has been run before and there is a large amount of data in
> the
> changelog topics, it might take a while to rebuild the local state stores
> from the
> changelog. During this time it would appear to be in REBALANCING, but it's
> actually
> just restoring.
>
> Just one possibility of many. How long did you let it run without seeing it
> stabilize?
> It's difficult to diagnose from just the small snippet of logs above, so I
> would
> try and take a look at the full picture over more than just a minute. There
> *should*
> be something slightly more helpful logged if it really is stuck in a cycle
> of endless
> rebalances (eg timing out on the session interval)
>
> On Wed, Sep 2, 2020 at 11:52 AM Steve Jones <jo...@gmail.com>
> wrote:
>
> > Just an addition to this in case someone can help, I'm seeing zero thread
> > activity in the rebalancing but I'm also not seeing anything being logged
> > by Kafka to indicate its doing anything on rebalancing (Logging level set
> > to ALL), producer and consumer code works fine but streams just appears
> to
> > hang.
> >
> > On Mon, 31 Aug 2020 at 12:49, Steve Jones <jo...@gmail.com>
> wrote:
> >
> >> When running an application on the Mac it works fine, when running
> >> exactly the same app and config on the Raspberry Pi it constantly says
> it
> >> is "Rebalancing" the streams
> >>
> >> 2020-08-31 12:47:11 INFO
> >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> version:
> >> 2.6.0
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> commitId:
> >> 62abe01bee039651
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
> >> startTimeMs: 1598903231499
> >>
> >> ''2020-08-31 12:47:11 WARNING org.apache.kafka.streams.StreamsConfig
> >> checkIfUnexpectedUserSpecifiedConsumerConfig Unexpected user-specified
> >> consumer config: enable.auto.commit found. User setting (true) will be
> >> ignored and the Streams default setting (false) will be used
> >>
> >> ''2020-08-31 12:47:11 INFO org.apache.kafka.streams.KafkaStreams
> setState
> >> stream-client [pi-test-84721b40-dfa1-4848-b3de-5c7561048403] State
> >> transition from CREATED to REBALANCING
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> com.businesssoa.home.events.filter.dispatcher.kafka.SensorPipe start
> Pipe
> >> STARTED
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> org.apache.kafka.streams.processor.internals.StreamThread run
> stream-thread
> >> [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1] Starting
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> org.apache.kafka.streams.processor.internals.StreamThread setState
> >> stream-thread
> [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1]
> >> State transition from CREATED to STARTING
> >>
> >> ''2020-08-31 12:47:11 INFO
> >> org.apache.kafka.clients.consumer.KafkaConsumer subscribe [Consumer
> >>
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> >> groupId=pi-test] Subscribed to topic(s): filtered-topic, reading-topic
> >>
> >> ''2020-08-31 12:47:11 INFO com.businesssoa.home.events.filter.App
> >> waitTillStarted Status is REBALANCING , 1
> >>
> >> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> >> [Producer
> >>
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-producer]
> >> Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
> >>
> >> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
> >> [Consumer
> >>
> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
> >> groupId=pi-test] Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
> >>
> >> ''2020-08-31 12:47:41 INFO com.businesssoa.home.events.filter.App
> >> waitTillStarted Status is REBALANCING , 2
> >>
> >> ''2020-08-31 12:48:11 INFO com.businesssoa.home.events.filter.App
> >> waitTillStarted Status is REBALANCING , 3
> >>
> >> Any guidance on how I can debug the streams as to why its constantly
> >> rebalancing?
> >>
> >> Steve
> >>
> >>
>
Re: Streams constantly reblancing,
Posted by Sophie Blee-Goldman <so...@confluent.io>.
Hey steve,
I guess the first question I have is, is the consumer group actually
rebalancing
or does KafkaStreams just appear to be "stuck" in the REBALANCING state? If
this application has been run before and there is a large amount of data in
the
changelog topics, it might take a while to rebuild the local state stores
from the
changelog. During this time it would appear to be in REBALANCING, but it's
actually
just restoring.
Just one possibility of many. How long did you let it run without seeing it
stabilize?
It's difficult to diagnose from just the small snippet of logs above, so I
would
try and take a look at the full picture over more than just a minute. There
*should*
be something slightly more helpful logged if it really is stuck in a cycle
of endless
rebalances (eg timing out on the session interval)
On Wed, Sep 2, 2020 at 11:52 AM Steve Jones <jo...@gmail.com> wrote:
> Just an addition to this in case someone can help, I'm seeing zero thread
> activity in the rebalancing but I'm also not seeing anything being logged
> by Kafka to indicate its doing anything on rebalancing (Logging level set
> to ALL), producer and consumer code works fine but streams just appears to
> hang.
>
> On Mon, 31 Aug 2020 at 12:49, Steve Jones <jo...@gmail.com> wrote:
>
>> When running an application on the Mac it works fine, when running
>> exactly the same app and config on the Raspberry Pi it constantly says it
>> is "Rebalancing" the streams
>>
>> 2020-08-31 12:47:11 INFO
>> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka version:
>> 2.6.0
>>
>> ''2020-08-31 12:47:11 INFO
>> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka commitId:
>> 62abe01bee039651
>>
>> ''2020-08-31 12:47:11 INFO
>> org.apache.kafka.common.utils.AppInfoParser$AppInfo <init> Kafka
>> startTimeMs: 1598903231499
>>
>> ''2020-08-31 12:47:11 WARNING org.apache.kafka.streams.StreamsConfig
>> checkIfUnexpectedUserSpecifiedConsumerConfig Unexpected user-specified
>> consumer config: enable.auto.commit found. User setting (true) will be
>> ignored and the Streams default setting (false) will be used
>>
>> ''2020-08-31 12:47:11 INFO org.apache.kafka.streams.KafkaStreams setState
>> stream-client [pi-test-84721b40-dfa1-4848-b3de-5c7561048403] State
>> transition from CREATED to REBALANCING
>>
>> ''2020-08-31 12:47:11 INFO
>> com.businesssoa.home.events.filter.dispatcher.kafka.SensorPipe start Pipe
>> STARTED
>>
>> ''2020-08-31 12:47:11 INFO
>> org.apache.kafka.streams.processor.internals.StreamThread run stream-thread
>> [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1] Starting
>>
>> ''2020-08-31 12:47:11 INFO
>> org.apache.kafka.streams.processor.internals.StreamThread setState
>> stream-thread [pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1]
>> State transition from CREATED to STARTING
>>
>> ''2020-08-31 12:47:11 INFO
>> org.apache.kafka.clients.consumer.KafkaConsumer subscribe [Consumer
>> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
>> groupId=pi-test] Subscribed to topic(s): filtered-topic, reading-topic
>>
>> ''2020-08-31 12:47:11 INFO com.businesssoa.home.events.filter.App
>> waitTillStarted Status is REBALANCING , 1
>>
>> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
>> [Producer
>> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-producer]
>> Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
>>
>> ''2020-08-31 12:47:12 INFO org.apache.kafka.clients.Metadata update
>> [Consumer
>> clientId=pi-test-84721b40-dfa1-4848-b3de-5c7561048403-StreamThread-1-consumer,
>> groupId=pi-test] Cluster ID: 1AOC2O8zSqq7nuQKACXFxQ
>>
>> ''2020-08-31 12:47:41 INFO com.businesssoa.home.events.filter.App
>> waitTillStarted Status is REBALANCING , 2
>>
>> ''2020-08-31 12:48:11 INFO com.businesssoa.home.events.filter.App
>> waitTillStarted Status is REBALANCING , 3
>>
>> Any guidance on how I can debug the streams as to why its constantly
>> rebalancing?
>>
>> Steve
>>
>>