You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Phil Luckhurst <ph...@encycle.com> on 2016/04/12 14:39:04 UTC
KafkaProducer 0.9.0.1 continually sends metadata requests
With debug logging turned on we've sometimes seen our logs filling up with the kafka producer sending metadata requests every 100ms e.g.
2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread | phil-pa-1] org.apache.kafka.clients.NetworkClient: Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=249,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}), isInitiatedByNetworkClient, createdTimeMs=1460108373592, sendTimeMs=0) to node 0
2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread | phil-pa-1] org.apache.kafka.clients.Metadata: Updated cluster metadata version 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions = [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0, replicas = [0,], isr = [0,]])
2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread | phil-pa-1] org.apache.kafka.clients.NetworkClient: Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=250,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}), isInitiatedByNetworkClient, createdTimeMs=1460108373698, sendTimeMs=0) to node 0
2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread | phil-pa-1] org.apache.kafka.clients.Metadata: Updated cluster metadata version 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions = [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0, replicas = [0,], isr = [0,]])
These metadata requests continue to be sent every 100ms (retry.backoff.ms) until we stop the process.
This only seems to happen if the KafkaProducer instance is created but not used to publish a message for 5 minutes. After 5 minutes (metadata.max.age.ms) the producer thread sends a metadata request to the server that has an empty topics list and the server responds with the partition information for *all* topics hosted on the server.
2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread | phil-pa-1] org.apache.kafka.clients.NetworkClient: Sending metadata request ClientRequest(expectResponse=true, callback=null, request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,client_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient, createdTimeMs=1460380599289, sendTimeMs=0) to node -1
If we then use that KafkaProducer instance to send a message the next 'Sending meta request' will just be for the topic we have sent the message to and this then triggers the flood of retry requests as noted above.
If we ensure we send the first message within the time set by metadata.max.age.ms (default 5 minutes) then everything works as expected and the metadata requests do not continually get retried.
In many cases I can understand that creating a KafkaProducer and then not using it within 5 minutes is not usual but in our case we're creating it when our REST based application starts up and we can't guarantee that a message will be published within that time. To get around this we are currently posting a test message to the topic right after creating the KafkaProducer prevents it happening.
I'm not sure if this is worthy of a fix but I thought I'd post it here in case someone else hits the same problem.
Regards,
Phil Luckhurst
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Ismael Juma <is...@juma.me.uk>.
Thanks Phil. I added the information to the JIRA. This needs to be
verified, but it may be possible that the fix for KAFKA-3306 will also fix
this as we won't be requesting all the topics any longer.
Ismael
On Wed, Apr 13, 2016 at 10:35 AM, Phil Luckhurst <phil.luckhurst@encycle.com
> wrote:
> Hi Ismael,
>
> The request does succeed and the reason it keeps requesting is a check in
> the Sender.run(long now) method.
>
> public void run(long now) {
> Cluster cluster = metadata.fetch();
> // get the list of partitions with data ready to send
> RecordAccumulator.ReadyCheckResult result =
> this.accumulator.ready(cluster, now);
>
> // if there are any partitions whose leaders are not known yet,
> force metadata update
> if (result.unknownLeadersExist)
> this.metadata.requestUpdate();
>
> It looks like the this.accumulator.ready(cluster, now) method checks the
> leader for each partition in the response against what it already had. In
> this case the original metadata request had the empty topic list so got
> information for all partitions but after using the producer the cluster
> only has the one topic in it which means this check sets
> unknownLeadersExist = true.
> Node leader = cluster.leaderFor(part);
> if (leader == null) {
> unknownLeadersExist = true;
>
> As you can see above the Sender.run methd checks for this in the result
> and then calls this.metadata.requestUpdate() which tirggers the metadata to
> be requested again. And of course the same thing happens when checking the
> next response and we're suddenly in the loop forever.
>
> Hope this helps,
>
> Phil
>
>
> -----Original Message-----
> From: ismaelj@gmail.com [mailto:ismaelj@gmail.com] On Behalf Of Ismael
> Juma
> Sent: 12 April 2016 16:24
> To: users@kafka.apache.org
> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
>
> Hi Jonathan,
>
> That makes sense, thanks.
>
> Phil, do you know if your metadata requests are succeeding? Retrying every
> retry.backoff.ms is expected if they fail, but not if they succeed. In
> terms of posting a comment to JIRA, you can create an account if you don't
> have one:
>
> https://issues.apache.org/jira/secure/Signup!default.jspa
>
> Ismael
>
> On Tue, Apr 12, 2016 at 3:33 PM, Jonathan Bond <jb...@netflix.com.invalid>
> wrote:
>
> > Ismael, In our case KAFKA-3358 caused frequent metadata requests
> > because we ended up swamping the broker. Getting all metadata is a
> > very expensive request, once all requests threads spent their majority
> > of time handling metadata requests, they'd start timing out. Timing
> > out would cause a new request to be made, which would increase the
> > needed metadata level - so when a response finally did arrive it was
> > never recent enough. To resolve we had to shut down the 7000 clients
> > and let the brokers catch-up, for other messages to start flowing
> > again. I can't remember if clients were sending at retry.backoff.ms or
> > timeout rate (it wasn't a fun day, and I don't want to recreate to
> > find out). We now make sure we don't start up producers until a message
> is ready to be sent.
> >
> > On Tue, Apr 12, 2016 at 6:59 AM Ismael Juma <is...@juma.me.uk> wrote:
> >
> > > Sorry, I should say that KAFKA-3306 will fix the issue where we
> > > request data for all topics instead of no topics. However, it seems
> > > like there is an additional issue where it seems like we are
> > > performing metadata
> > requests
> > > too frequently. Phil, can you please add this information to
> > > KAFKA-3358
> > so
> > > that we can figure out if more needs to be done?
> > >
> > > Ismael
> > >
> > > On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk>
> wrote:
> > >
> > > > Note that this should be fixed as part of
> > > > https://issues.apache.org/jira/browse/KAFKA-3306
> > > >
> > > > Ismael
> > > >
> > > > On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> > > > phil.luckhurst@encycle.com> wrote:
> > > >
> > > >> Thanks Jonathan, I didn't spot that JIRA.
> > > >>
> > > >> Phil
> > > >>
> > > >> -----Original Message-----
> > > >> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
> > > >> Sent: 12 April 2016 14:08
> > > >> To: users@kafka.apache.org
> > > >> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata
> > > >> requests
> > > >>
> > > >> Phil,
> > > >> In our case this bug placed significant load on our brokers. We
> > raised a
> > > >> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
> > > >> resolved.
> > > >>
> > > >> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
> > > >> phil.luckhurst@encycle.com>
> > > >> wrote:
> > > >>
> > > >> > With debug logging turned on we've sometimes seen our logs
> > > >> > filling
> > up
> > > >> > with the kafka producer sending metadata requests every 100ms e.g.
> > > >> >
> > > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > > >> > phil-pa-1]
> > > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > > >> > request ClientRequest(expectResponse=true, callback=null,
> > > >> >
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> > > >> > ,client_id=phil-pa-1},
> > > >> > body={topics=[phil-pa-1-device-update]}),
> > > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373592,
> > sendTimeMs=0)
> > > >> > to node 0
> > > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > > >> > phil-pa-1]
> > > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata
> > > >> > version
> > > >> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)],
> > > >> > partitions = [Partition(topic = phil-pa-1-device-update,
> > > >> > partition = 0, leader =
> > 0,
> > > >> > replicas = [0,], isr = [0,]])
> > > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > > >> > phil-pa-1]
> > > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > > >> > request ClientRequest(expectResponse=true, callback=null,
> > > >> >
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> > > >> > ,client_id=phil-pa-1},
> > > >> > body={topics=[phil-pa-1-device-update]}),
> > > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373698,
> > sendTimeMs=0)
> > > >> > to node 0
> > > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > > >> > phil-pa-1]
> > > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata
> > > >> > version
> > > >> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)],
> > > >> > partitions = [Partition(topic = phil-pa-1-device-update,
> > > >> > partition = 0, leader =
> > 0,
> > > >> > replicas = [0,], isr = [0,]])
> > > >> >
> > > >> > These metadata requests continue to be sent every 100ms
> > > >> > (retry.backoff.ms) until we stop the process.
> > > >> >
> > > >> > This only seems to happen if the KafkaProducer instance is
> > > >> > created
> > but
> > > >> > not used to publish a message for 5 minutes. After 5 minutes (
> > > >> > metadata.max.age.ms) the producer thread sends a metadata
> > > >> > request
> > to
> > > >> > the server that has an empty topics list and the server
> > > >> > responds
> > with
> > > >> > the partition information for *all* topics hosted on the server.
> > > >> >
> > > >> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> > > >> > phil-pa-1]
> > > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > > >> > request ClientRequest(expectResponse=true, callback=null,
> > > >> >
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> > > >> > lient_id=phil-pa-1}, body={topics=[]}),
> > > >> > isInitiatedByNetworkClient, createdTimeMs=1460380599289,
> > > >> > sendTimeMs=0) to node -1
> > > >> >
> > > >> > If we then use that KafkaProducer instance to send a message
> > > >> > the
> > next
> > > >> > 'Sending meta request' will just be for the topic we have sent
> > > >> > the message to and this then triggers the flood of retry
> > > >> > requests as
> > noted
> > > >> above.
> > > >> >
> > > >> > If we ensure we send the first message within the time set by
> > > >> > metadata.max.age.ms (default 5 minutes) then everything works
> > > >> > as expected and the metadata requests do not continually get
> retried.
> > > >> >
> > > >> > In many cases I can understand that creating a KafkaProducer
> > > >> > and
> > then
> > > >> > not using it within 5 minutes is not usual but in our case
> > > >> > we're creating it when our REST based application starts up and
> > > >> > we can't guarantee that a message will be published within that
> > > >> > time. To get around this we are currently posting a test
> > > >> > message to the topic
> > right
> > > >> > after creating the KafkaProducer prevents it happening.
> > > >> >
> > > >> > I'm not sure if this is worthy of a fix but I thought I'd post
> > > >> > it
> > here
> > > >> > in case someone else hits the same problem.
> > > >> >
> > > >> > Regards,
> > > >> > Phil Luckhurst
> > > >> >
> > > >>
> > > >
> > > >
> > >
> >
>
RE: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Phil Luckhurst <ph...@encycle.com>.
Hi Ismael,
The request does succeed and the reason it keeps requesting is a check in the Sender.run(long now) method.
public void run(long now) {
Cluster cluster = metadata.fetch();
// get the list of partitions with data ready to send
RecordAccumulator.ReadyCheckResult result = this.accumulator.ready(cluster, now);
// if there are any partitions whose leaders are not known yet, force metadata update
if (result.unknownLeadersExist)
this.metadata.requestUpdate();
It looks like the this.accumulator.ready(cluster, now) method checks the leader for each partition in the response against what it already had. In this case the original metadata request had the empty topic list so got information for all partitions but after using the producer the cluster only has the one topic in it which means this check sets unknownLeadersExist = true.
Node leader = cluster.leaderFor(part);
if (leader == null) {
unknownLeadersExist = true;
As you can see above the Sender.run methd checks for this in the result and then calls this.metadata.requestUpdate() which tirggers the metadata to be requested again. And of course the same thing happens when checking the next response and we're suddenly in the loop forever.
Hope this helps,
Phil
-----Original Message-----
From: ismaelj@gmail.com [mailto:ismaelj@gmail.com] On Behalf Of Ismael Juma
Sent: 12 April 2016 16:24
To: users@kafka.apache.org
Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Hi Jonathan,
That makes sense, thanks.
Phil, do you know if your metadata requests are succeeding? Retrying every retry.backoff.ms is expected if they fail, but not if they succeed. In terms of posting a comment to JIRA, you can create an account if you don't have one:
https://issues.apache.org/jira/secure/Signup!default.jspa
Ismael
On Tue, Apr 12, 2016 at 3:33 PM, Jonathan Bond <jb...@netflix.com.invalid>
wrote:
> Ismael, In our case KAFKA-3358 caused frequent metadata requests
> because we ended up swamping the broker. Getting all metadata is a
> very expensive request, once all requests threads spent their majority
> of time handling metadata requests, they'd start timing out. Timing
> out would cause a new request to be made, which would increase the
> needed metadata level - so when a response finally did arrive it was
> never recent enough. To resolve we had to shut down the 7000 clients
> and let the brokers catch-up, for other messages to start flowing
> again. I can't remember if clients were sending at retry.backoff.ms or
> timeout rate (it wasn't a fun day, and I don't want to recreate to
> find out). We now make sure we don't start up producers until a message is ready to be sent.
>
> On Tue, Apr 12, 2016 at 6:59 AM Ismael Juma <is...@juma.me.uk> wrote:
>
> > Sorry, I should say that KAFKA-3306 will fix the issue where we
> > request data for all topics instead of no topics. However, it seems
> > like there is an additional issue where it seems like we are
> > performing metadata
> requests
> > too frequently. Phil, can you please add this information to
> > KAFKA-3358
> so
> > that we can figure out if more needs to be done?
> >
> > Ismael
> >
> > On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk> wrote:
> >
> > > Note that this should be fixed as part of
> > > https://issues.apache.org/jira/browse/KAFKA-3306
> > >
> > > Ismael
> > >
> > > On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> > > phil.luckhurst@encycle.com> wrote:
> > >
> > >> Thanks Jonathan, I didn't spot that JIRA.
> > >>
> > >> Phil
> > >>
> > >> -----Original Message-----
> > >> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
> > >> Sent: 12 April 2016 14:08
> > >> To: users@kafka.apache.org
> > >> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata
> > >> requests
> > >>
> > >> Phil,
> > >> In our case this bug placed significant load on our brokers. We
> raised a
> > >> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
> > >> resolved.
> > >>
> > >> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
> > >> phil.luckhurst@encycle.com>
> > >> wrote:
> > >>
> > >> > With debug logging turned on we've sometimes seen our logs
> > >> > filling
> up
> > >> > with the kafka producer sending metadata requests every 100ms e.g.
> > >> >
> > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > >> > request ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> > >> > ,client_id=phil-pa-1},
> > >> > body={topics=[phil-pa-1-device-update]}),
> > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373592,
> sendTimeMs=0)
> > >> > to node 0
> > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata
> > >> > version
> > >> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)],
> > >> > partitions = [Partition(topic = phil-pa-1-device-update,
> > >> > partition = 0, leader =
> 0,
> > >> > replicas = [0,], isr = [0,]])
> > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > >> > request ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> > >> > ,client_id=phil-pa-1},
> > >> > body={topics=[phil-pa-1-device-update]}),
> > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373698,
> sendTimeMs=0)
> > >> > to node 0
> > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata
> > >> > version
> > >> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)],
> > >> > partitions = [Partition(topic = phil-pa-1-device-update,
> > >> > partition = 0, leader =
> 0,
> > >> > replicas = [0,], isr = [0,]])
> > >> >
> > >> > These metadata requests continue to be sent every 100ms
> > >> > (retry.backoff.ms) until we stop the process.
> > >> >
> > >> > This only seems to happen if the KafkaProducer instance is
> > >> > created
> but
> > >> > not used to publish a message for 5 minutes. After 5 minutes (
> > >> > metadata.max.age.ms) the producer thread sends a metadata
> > >> > request
> to
> > >> > the server that has an empty topics list and the server
> > >> > responds
> with
> > >> > the partition information for *all* topics hosted on the server.
> > >> >
> > >> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata
> > >> > request ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> > >> > lient_id=phil-pa-1}, body={topics=[]}),
> > >> > isInitiatedByNetworkClient, createdTimeMs=1460380599289,
> > >> > sendTimeMs=0) to node -1
> > >> >
> > >> > If we then use that KafkaProducer instance to send a message
> > >> > the
> next
> > >> > 'Sending meta request' will just be for the topic we have sent
> > >> > the message to and this then triggers the flood of retry
> > >> > requests as
> noted
> > >> above.
> > >> >
> > >> > If we ensure we send the first message within the time set by
> > >> > metadata.max.age.ms (default 5 minutes) then everything works
> > >> > as expected and the metadata requests do not continually get retried.
> > >> >
> > >> > In many cases I can understand that creating a KafkaProducer
> > >> > and
> then
> > >> > not using it within 5 minutes is not usual but in our case
> > >> > we're creating it when our REST based application starts up and
> > >> > we can't guarantee that a message will be published within that
> > >> > time. To get around this we are currently posting a test
> > >> > message to the topic
> right
> > >> > after creating the KafkaProducer prevents it happening.
> > >> >
> > >> > I'm not sure if this is worthy of a fix but I thought I'd post
> > >> > it
> here
> > >> > in case someone else hits the same problem.
> > >> >
> > >> > Regards,
> > >> > Phil Luckhurst
> > >> >
> > >>
> > >
> > >
> >
>
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Ismael Juma <is...@juma.me.uk>.
Hi Jonathan,
That makes sense, thanks.
Phil, do you know if your metadata requests are succeeding? Retrying every
retry.backoff.ms is expected if they fail, but not if they succeed. In
terms of posting a comment to JIRA, you can create an account if you don't
have one:
https://issues.apache.org/jira/secure/Signup!default.jspa
Ismael
On Tue, Apr 12, 2016 at 3:33 PM, Jonathan Bond <jb...@netflix.com.invalid>
wrote:
> Ismael, In our case KAFKA-3358 caused frequent metadata requests because we
> ended up swamping the broker. Getting all metadata is a very expensive
> request, once all requests threads spent their majority of time handling
> metadata requests, they'd start timing out. Timing out would cause a new
> request to be made, which would increase the needed metadata level - so
> when a response finally did arrive it was never recent enough. To resolve
> we had to shut down the 7000 clients and let the brokers catch-up, for
> other messages to start flowing again. I can't remember if clients were
> sending at retry.backoff.ms or timeout rate (it wasn't a fun day, and I
> don't want to recreate to find out). We now make sure we don't start up
> producers until a message is ready to be sent.
>
> On Tue, Apr 12, 2016 at 6:59 AM Ismael Juma <is...@juma.me.uk> wrote:
>
> > Sorry, I should say that KAFKA-3306 will fix the issue where we request
> > data for all topics instead of no topics. However, it seems like there is
> > an additional issue where it seems like we are performing metadata
> requests
> > too frequently. Phil, can you please add this information to KAFKA-3358
> so
> > that we can figure out if more needs to be done?
> >
> > Ismael
> >
> > On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk> wrote:
> >
> > > Note that this should be fixed as part of
> > > https://issues.apache.org/jira/browse/KAFKA-3306
> > >
> > > Ismael
> > >
> > > On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> > > phil.luckhurst@encycle.com> wrote:
> > >
> > >> Thanks Jonathan, I didn't spot that JIRA.
> > >>
> > >> Phil
> > >>
> > >> -----Original Message-----
> > >> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
> > >> Sent: 12 April 2016 14:08
> > >> To: users@kafka.apache.org
> > >> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
> > >>
> > >> Phil,
> > >> In our case this bug placed significant load on our brokers. We
> raised a
> > >> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
> > >> resolved.
> > >>
> > >> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
> > >> phil.luckhurst@encycle.com>
> > >> wrote:
> > >>
> > >> > With debug logging turned on we've sometimes seen our logs filling
> up
> > >> > with the kafka producer sending metadata requests every 100ms e.g.
> > >> >
> > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > >> > ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> > >> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373592,
> sendTimeMs=0)
> > >> > to node 0
> > >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> > >> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> > >> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader =
> 0,
> > >> > replicas = [0,], isr = [0,]])
> > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > >> > ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> > >> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> > >> > isInitiatedByNetworkClient, createdTimeMs=1460108373698,
> sendTimeMs=0)
> > >> > to node 0
> > >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> > >> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> > >> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader =
> 0,
> > >> > replicas = [0,], isr = [0,]])
> > >> >
> > >> > These metadata requests continue to be sent every 100ms
> > >> > (retry.backoff.ms) until we stop the process.
> > >> >
> > >> > This only seems to happen if the KafkaProducer instance is created
> but
> > >> > not used to publish a message for 5 minutes. After 5 minutes (
> > >> > metadata.max.age.ms) the producer thread sends a metadata request
> to
> > >> > the server that has an empty topics list and the server responds
> with
> > >> > the partition information for *all* topics hosted on the server.
> > >> >
> > >> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> > >> > phil-pa-1]
> > >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > >> > ClientRequest(expectResponse=true, callback=null,
> > >> >
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> > >> > lient_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient,
> > >> > createdTimeMs=1460380599289,
> > >> > sendTimeMs=0) to node -1
> > >> >
> > >> > If we then use that KafkaProducer instance to send a message the
> next
> > >> > 'Sending meta request' will just be for the topic we have sent the
> > >> > message to and this then triggers the flood of retry requests as
> noted
> > >> above.
> > >> >
> > >> > If we ensure we send the first message within the time set by
> > >> > metadata.max.age.ms (default 5 minutes) then everything works as
> > >> > expected and the metadata requests do not continually get retried.
> > >> >
> > >> > In many cases I can understand that creating a KafkaProducer and
> then
> > >> > not using it within 5 minutes is not usual but in our case we're
> > >> > creating it when our REST based application starts up and we can't
> > >> > guarantee that a message will be published within that time. To get
> > >> > around this we are currently posting a test message to the topic
> right
> > >> > after creating the KafkaProducer prevents it happening.
> > >> >
> > >> > I'm not sure if this is worthy of a fix but I thought I'd post it
> here
> > >> > in case someone else hits the same problem.
> > >> >
> > >> > Regards,
> > >> > Phil Luckhurst
> > >> >
> > >>
> > >
> > >
> >
>
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Jonathan Bond <jb...@netflix.com.INVALID>.
Ismael, In our case KAFKA-3358 caused frequent metadata requests because we
ended up swamping the broker. Getting all metadata is a very expensive
request, once all requests threads spent their majority of time handling
metadata requests, they'd start timing out. Timing out would cause a new
request to be made, which would increase the needed metadata level - so
when a response finally did arrive it was never recent enough. To resolve
we had to shut down the 7000 clients and let the brokers catch-up, for
other messages to start flowing again. I can't remember if clients were
sending at retry.backoff.ms or timeout rate (it wasn't a fun day, and I
don't want to recreate to find out). We now make sure we don't start up
producers until a message is ready to be sent.
On Tue, Apr 12, 2016 at 6:59 AM Ismael Juma <is...@juma.me.uk> wrote:
> Sorry, I should say that KAFKA-3306 will fix the issue where we request
> data for all topics instead of no topics. However, it seems like there is
> an additional issue where it seems like we are performing metadata requests
> too frequently. Phil, can you please add this information to KAFKA-3358 so
> that we can figure out if more needs to be done?
>
> Ismael
>
> On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk> wrote:
>
> > Note that this should be fixed as part of
> > https://issues.apache.org/jira/browse/KAFKA-3306
> >
> > Ismael
> >
> > On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> > phil.luckhurst@encycle.com> wrote:
> >
> >> Thanks Jonathan, I didn't spot that JIRA.
> >>
> >> Phil
> >>
> >> -----Original Message-----
> >> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
> >> Sent: 12 April 2016 14:08
> >> To: users@kafka.apache.org
> >> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
> >>
> >> Phil,
> >> In our case this bug placed significant load on our brokers. We raised a
> >> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
> >> resolved.
> >>
> >> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
> >> phil.luckhurst@encycle.com>
> >> wrote:
> >>
> >> > With debug logging turned on we've sometimes seen our logs filling up
> >> > with the kafka producer sending metadata requests every 100ms e.g.
> >> >
> >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> >> > phil-pa-1]
> >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> >> > ClientRequest(expectResponse=true, callback=null,
> >> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> >> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> >> > isInitiatedByNetworkClient, createdTimeMs=1460108373592, sendTimeMs=0)
> >> > to node 0
> >> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> >> > phil-pa-1]
> >> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> >> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> >> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> >> > replicas = [0,], isr = [0,]])
> >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> >> > phil-pa-1]
> >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> >> > ClientRequest(expectResponse=true, callback=null,
> >> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> >> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> >> > isInitiatedByNetworkClient, createdTimeMs=1460108373698, sendTimeMs=0)
> >> > to node 0
> >> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> >> > phil-pa-1]
> >> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> >> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> >> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> >> > replicas = [0,], isr = [0,]])
> >> >
> >> > These metadata requests continue to be sent every 100ms
> >> > (retry.backoff.ms) until we stop the process.
> >> >
> >> > This only seems to happen if the KafkaProducer instance is created but
> >> > not used to publish a message for 5 minutes. After 5 minutes (
> >> > metadata.max.age.ms) the producer thread sends a metadata request to
> >> > the server that has an empty topics list and the server responds with
> >> > the partition information for *all* topics hosted on the server.
> >> >
> >> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> >> > phil-pa-1]
> >> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> >> > ClientRequest(expectResponse=true, callback=null,
> >> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> >> > lient_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient,
> >> > createdTimeMs=1460380599289,
> >> > sendTimeMs=0) to node -1
> >> >
> >> > If we then use that KafkaProducer instance to send a message the next
> >> > 'Sending meta request' will just be for the topic we have sent the
> >> > message to and this then triggers the flood of retry requests as noted
> >> above.
> >> >
> >> > If we ensure we send the first message within the time set by
> >> > metadata.max.age.ms (default 5 minutes) then everything works as
> >> > expected and the metadata requests do not continually get retried.
> >> >
> >> > In many cases I can understand that creating a KafkaProducer and then
> >> > not using it within 5 minutes is not usual but in our case we're
> >> > creating it when our REST based application starts up and we can't
> >> > guarantee that a message will be published within that time. To get
> >> > around this we are currently posting a test message to the topic right
> >> > after creating the KafkaProducer prevents it happening.
> >> >
> >> > I'm not sure if this is worthy of a fix but I thought I'd post it here
> >> > in case someone else hits the same problem.
> >> >
> >> > Regards,
> >> > Phil Luckhurst
> >> >
> >>
> >
> >
>
RE: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Phil Luckhurst <ph...@encycle.com>.
Ismael,
I don't see how I can add any information to KAFKA-3358 as I haven't got an account?
Phil
-----Original Message-----
From: ismaelj@gmail.com [mailto:ismaelj@gmail.com] On Behalf Of Ismael Juma
Sent: 12 April 2016 14:59
To: users@kafka.apache.org
Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Sorry, I should say that KAFKA-3306 will fix the issue where we request data for all topics instead of no topics. However, it seems like there is an additional issue where it seems like we are performing metadata requests too frequently. Phil, can you please add this information to KAFKA-3358 so that we can figure out if more needs to be done?
Ismael
On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk> wrote:
> Note that this should be fixed as part of
> https://issues.apache.org/jira/browse/KAFKA-3306
>
> Ismael
>
> On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> phil.luckhurst@encycle.com> wrote:
>
>> Thanks Jonathan, I didn't spot that JIRA.
>>
>> Phil
>>
>> -----Original Message-----
>> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
>> Sent: 12 April 2016 14:08
>> To: users@kafka.apache.org
>> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata
>> requests
>>
>> Phil,
>> In our case this bug placed significant load on our brokers. We
>> raised a bug https://issues.apache.org/jira/browse/KAFKA-3358 to get
>> this resolved.
>>
>> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
>> phil.luckhurst@encycle.com>
>> wrote:
>>
>> > With debug logging turned on we've sometimes seen our logs filling
>> > up with the kafka producer sending metadata requests every 100ms e.g.
>> >
>> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=
>> > 249 ,client_id=phil-pa-1},
>> > body={topics=[phil-pa-1-device-update]}),
>> > isInitiatedByNetworkClient, createdTimeMs=1460108373592,
>> > sendTimeMs=0) to node 0
>> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
>> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
>> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader =
>> > 0, replicas = [0,], isr = [0,]])
>> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=
>> > 250 ,client_id=phil-pa-1},
>> > body={topics=[phil-pa-1-device-update]}),
>> > isInitiatedByNetworkClient, createdTimeMs=1460108373698,
>> > sendTimeMs=0) to node 0
>> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
>> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
>> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader =
>> > 0, replicas = [0,], isr = [0,]])
>> >
>> > These metadata requests continue to be sent every 100ms
>> > (retry.backoff.ms) until we stop the process.
>> >
>> > This only seems to happen if the KafkaProducer instance is created
>> > but not used to publish a message for 5 minutes. After 5 minutes (
>> > metadata.max.age.ms) the producer thread sends a metadata request
>> > to the server that has an empty topics list and the server responds
>> > with the partition information for *all* topics hosted on the server.
>> >
>> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=
>> > 0,c lient_id=phil-pa-1}, body={topics=[]}),
>> > isInitiatedByNetworkClient, createdTimeMs=1460380599289,
>> > sendTimeMs=0) to node -1
>> >
>> > If we then use that KafkaProducer instance to send a message the
>> > next 'Sending meta request' will just be for the topic we have sent
>> > the message to and this then triggers the flood of retry requests
>> > as noted
>> above.
>> >
>> > If we ensure we send the first message within the time set by
>> > metadata.max.age.ms (default 5 minutes) then everything works as
>> > expected and the metadata requests do not continually get retried.
>> >
>> > In many cases I can understand that creating a KafkaProducer and
>> > then not using it within 5 minutes is not usual but in our case
>> > we're creating it when our REST based application starts up and we
>> > can't guarantee that a message will be published within that time.
>> > To get around this we are currently posting a test message to the
>> > topic right after creating the KafkaProducer prevents it happening.
>> >
>> > I'm not sure if this is worthy of a fix but I thought I'd post it
>> > here in case someone else hits the same problem.
>> >
>> > Regards,
>> > Phil Luckhurst
>> >
>>
>
>
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Ismael Juma <is...@juma.me.uk>.
Sorry, I should say that KAFKA-3306 will fix the issue where we request
data for all topics instead of no topics. However, it seems like there is
an additional issue where it seems like we are performing metadata requests
too frequently. Phil, can you please add this information to KAFKA-3358 so
that we can figure out if more needs to be done?
Ismael
On Tue, Apr 12, 2016 at 2:52 PM, Ismael Juma <is...@juma.me.uk> wrote:
> Note that this should be fixed as part of
> https://issues.apache.org/jira/browse/KAFKA-3306
>
> Ismael
>
> On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <
> phil.luckhurst@encycle.com> wrote:
>
>> Thanks Jonathan, I didn't spot that JIRA.
>>
>> Phil
>>
>> -----Original Message-----
>> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
>> Sent: 12 April 2016 14:08
>> To: users@kafka.apache.org
>> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
>>
>> Phil,
>> In our case this bug placed significant load on our brokers. We raised a
>> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
>> resolved.
>>
>> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <
>> phil.luckhurst@encycle.com>
>> wrote:
>>
>> > With debug logging turned on we've sometimes seen our logs filling up
>> > with the kafka producer sending metadata requests every 100ms e.g.
>> >
>> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
>> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
>> > isInitiatedByNetworkClient, createdTimeMs=1460108373592, sendTimeMs=0)
>> > to node 0
>> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
>> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
>> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
>> > replicas = [0,], isr = [0,]])
>> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
>> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
>> > isInitiatedByNetworkClient, createdTimeMs=1460108373698, sendTimeMs=0)
>> > to node 0
>> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
>> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
>> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
>> > replicas = [0,], isr = [0,]])
>> >
>> > These metadata requests continue to be sent every 100ms
>> > (retry.backoff.ms) until we stop the process.
>> >
>> > This only seems to happen if the KafkaProducer instance is created but
>> > not used to publish a message for 5 minutes. After 5 minutes (
>> > metadata.max.age.ms) the producer thread sends a metadata request to
>> > the server that has an empty topics list and the server responds with
>> > the partition information for *all* topics hosted on the server.
>> >
>> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
>> > phil-pa-1]
>> > org.apache.kafka.clients.NetworkClient: Sending metadata request
>> > ClientRequest(expectResponse=true, callback=null,
>> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
>> > lient_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient,
>> > createdTimeMs=1460380599289,
>> > sendTimeMs=0) to node -1
>> >
>> > If we then use that KafkaProducer instance to send a message the next
>> > 'Sending meta request' will just be for the topic we have sent the
>> > message to and this then triggers the flood of retry requests as noted
>> above.
>> >
>> > If we ensure we send the first message within the time set by
>> > metadata.max.age.ms (default 5 minutes) then everything works as
>> > expected and the metadata requests do not continually get retried.
>> >
>> > In many cases I can understand that creating a KafkaProducer and then
>> > not using it within 5 minutes is not usual but in our case we're
>> > creating it when our REST based application starts up and we can't
>> > guarantee that a message will be published within that time. To get
>> > around this we are currently posting a test message to the topic right
>> > after creating the KafkaProducer prevents it happening.
>> >
>> > I'm not sure if this is worthy of a fix but I thought I'd post it here
>> > in case someone else hits the same problem.
>> >
>> > Regards,
>> > Phil Luckhurst
>> >
>>
>
>
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Ismael Juma <is...@juma.me.uk>.
Note that this should be fixed as part of
https://issues.apache.org/jira/browse/KAFKA-3306
Ismael
On Tue, Apr 12, 2016 at 2:17 PM, Phil Luckhurst <ph...@encycle.com>
wrote:
> Thanks Jonathan, I didn't spot that JIRA.
>
> Phil
>
> -----Original Message-----
> From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
> Sent: 12 April 2016 14:08
> To: users@kafka.apache.org
> Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
>
> Phil,
> In our case this bug placed significant load on our brokers. We raised a
> bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this
> resolved.
>
> On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <phil.luckhurst@encycle.com
> >
> wrote:
>
> > With debug logging turned on we've sometimes seen our logs filling up
> > with the kafka producer sending metadata requests every 100ms e.g.
> >
> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > phil-pa-1]
> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > ClientRequest(expectResponse=true, callback=null,
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> > isInitiatedByNetworkClient, createdTimeMs=1460108373592, sendTimeMs=0)
> > to node 0
> > 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> > phil-pa-1]
> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> > 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> > replicas = [0,], isr = [0,]])
> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > phil-pa-1]
> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > ClientRequest(expectResponse=true, callback=null,
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> > ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> > isInitiatedByNetworkClient, createdTimeMs=1460108373698, sendTimeMs=0)
> > to node 0
> > 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> > phil-pa-1]
> > org.apache.kafka.clients.Metadata: Updated cluster metadata version
> > 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> > [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> > replicas = [0,], isr = [0,]])
> >
> > These metadata requests continue to be sent every 100ms
> > (retry.backoff.ms) until we stop the process.
> >
> > This only seems to happen if the KafkaProducer instance is created but
> > not used to publish a message for 5 minutes. After 5 minutes (
> > metadata.max.age.ms) the producer thread sends a metadata request to
> > the server that has an empty topics list and the server responds with
> > the partition information for *all* topics hosted on the server.
> >
> > 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> > phil-pa-1]
> > org.apache.kafka.clients.NetworkClient: Sending metadata request
> > ClientRequest(expectResponse=true, callback=null,
> > request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> > lient_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient,
> > createdTimeMs=1460380599289,
> > sendTimeMs=0) to node -1
> >
> > If we then use that KafkaProducer instance to send a message the next
> > 'Sending meta request' will just be for the topic we have sent the
> > message to and this then triggers the flood of retry requests as noted
> above.
> >
> > If we ensure we send the first message within the time set by
> > metadata.max.age.ms (default 5 minutes) then everything works as
> > expected and the metadata requests do not continually get retried.
> >
> > In many cases I can understand that creating a KafkaProducer and then
> > not using it within 5 minutes is not usual but in our case we're
> > creating it when our REST based application starts up and we can't
> > guarantee that a message will be published within that time. To get
> > around this we are currently posting a test message to the topic right
> > after creating the KafkaProducer prevents it happening.
> >
> > I'm not sure if this is worthy of a fix but I thought I'd post it here
> > in case someone else hits the same problem.
> >
> > Regards,
> > Phil Luckhurst
> >
>
RE: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Phil Luckhurst <ph...@encycle.com>.
Thanks Jonathan, I didn't spot that JIRA.
Phil
-----Original Message-----
From: Jonathan Bond [mailto:jbond@netflix.com.INVALID]
Sent: 12 April 2016 14:08
To: users@kafka.apache.org
Subject: Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Phil,
In our case this bug placed significant load on our brokers. We raised a bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this resolved.
On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <ph...@encycle.com>
wrote:
> With debug logging turned on we've sometimes seen our logs filling up
> with the kafka producer sending metadata requests every 100ms e.g.
>
> 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=249
> ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> isInitiatedByNetworkClient, createdTimeMs=1460108373592, sendTimeMs=0)
> to node 0
> 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread |
> phil-pa-1]
> org.apache.kafka.clients.Metadata: Updated cluster metadata version
> 248 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> replicas = [0,], isr = [0,]])
> 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=250
> ,client_id=phil-pa-1}, body={topics=[phil-pa-1-device-update]}),
> isInitiatedByNetworkClient, createdTimeMs=1460108373698, sendTimeMs=0)
> to node 0
> 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread |
> phil-pa-1]
> org.apache.kafka.clients.Metadata: Updated cluster metadata version
> 249 to Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> replicas = [0,], isr = [0,]])
>
> These metadata requests continue to be sent every 100ms
> (retry.backoff.ms) until we stop the process.
>
> This only seems to happen if the KafkaProducer instance is created but
> not used to publish a message for 5 minutes. After 5 minutes (
> metadata.max.age.ms) the producer thread sends a metadata request to
> the server that has an empty topics list and the server responds with
> the partition information for *all* topics hosted on the server.
>
> 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread |
> phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,c
> lient_id=phil-pa-1}, body={topics=[]}), isInitiatedByNetworkClient,
> createdTimeMs=1460380599289,
> sendTimeMs=0) to node -1
>
> If we then use that KafkaProducer instance to send a message the next
> 'Sending meta request' will just be for the topic we have sent the
> message to and this then triggers the flood of retry requests as noted above.
>
> If we ensure we send the first message within the time set by
> metadata.max.age.ms (default 5 minutes) then everything works as
> expected and the metadata requests do not continually get retried.
>
> In many cases I can understand that creating a KafkaProducer and then
> not using it within 5 minutes is not usual but in our case we're
> creating it when our REST based application starts up and we can't
> guarantee that a message will be published within that time. To get
> around this we are currently posting a test message to the topic right
> after creating the KafkaProducer prevents it happening.
>
> I'm not sure if this is worthy of a fix but I thought I'd post it here
> in case someone else hits the same problem.
>
> Regards,
> Phil Luckhurst
>
Re: KafkaProducer 0.9.0.1 continually sends metadata requests
Posted by Jonathan Bond <jb...@netflix.com.INVALID>.
Phil,
In our case this bug placed significant load on our brokers. We raised a
bug https://issues.apache.org/jira/browse/KAFKA-3358 to get this resolved.
On Tue, Apr 12, 2016 at 5:39 AM Phil Luckhurst <ph...@encycle.com>
wrote:
> With debug logging turned on we've sometimes seen our logs filling up with
> the kafka producer sending metadata requests every 100ms e.g.
>
> 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread | phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=249,client_id=phil-pa-1},
> body={topics=[phil-pa-1-device-update]}), isInitiatedByNetworkClient,
> createdTimeMs=1460108373592, sendTimeMs=0) to node 0
> 2016-04-08 10:39:33,592 DEBUG [kafka-producer-network-thread | phil-pa-1]
> org.apache.kafka.clients.Metadata: Updated cluster metadata version 248 to
> Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> replicas = [0,], isr = [0,]])
> 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread | phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=250,client_id=phil-pa-1},
> body={topics=[phil-pa-1-device-update]}), isInitiatedByNetworkClient,
> createdTimeMs=1460108373698, sendTimeMs=0) to node 0
> 2016-04-08 10:39:33,698 DEBUG [kafka-producer-network-thread | phil-pa-1]
> org.apache.kafka.clients.Metadata: Updated cluster metadata version 249 to
> Cluster(nodes = [Node(0, ta-eng-kafka2, 9092)], partitions =
> [Partition(topic = phil-pa-1-device-update, partition = 0, leader = 0,
> replicas = [0,], isr = [0,]])
>
> These metadata requests continue to be sent every 100ms (retry.backoff.ms)
> until we stop the process.
>
> This only seems to happen if the KafkaProducer instance is created but not
> used to publish a message for 5 minutes. After 5 minutes (
> metadata.max.age.ms) the producer thread sends a metadata request to the
> server that has an empty topics list and the server responds with the
> partition information for *all* topics hosted on the server.
>
> 2016-04-11 14:16:39,320 DEBUG [kafka-producer-network-thread | phil-pa-1]
> org.apache.kafka.clients.NetworkClient: Sending metadata request
> ClientRequest(expectResponse=true, callback=null,
> request=RequestSend(header={api_key=3,api_version=0,correlation_id=0,client_id=phil-pa-1},
> body={topics=[]}), isInitiatedByNetworkClient, createdTimeMs=1460380599289,
> sendTimeMs=0) to node -1
>
> If we then use that KafkaProducer instance to send a message the next
> 'Sending meta request' will just be for the topic we have sent the message
> to and this then triggers the flood of retry requests as noted above.
>
> If we ensure we send the first message within the time set by
> metadata.max.age.ms (default 5 minutes) then everything works as expected
> and the metadata requests do not continually get retried.
>
> In many cases I can understand that creating a KafkaProducer and then not
> using it within 5 minutes is not usual but in our case we're creating it
> when our REST based application starts up and we can't guarantee that a
> message will be published within that time. To get around this we are
> currently posting a test message to the topic right after creating the
> KafkaProducer prevents it happening.
>
> I'm not sure if this is worthy of a fix but I thought I'd post it here in
> case someone else hits the same problem.
>
> Regards,
> Phil Luckhurst
>