Producer message acknowledgement taking a constant 1 second on v0.9.4

[mfontanini]

Description

I have some code that writes into kafka and then waits for acknowledgements while polling on the producer. This was working fine on v0.9.3 but now that I upgraded to v0.9.4 (and this is also happening on HEAD), it seems like every time I poll for acks, I always end up waiting a second, even if I write a single message and reduce the poll timeout to e.g. 100ms.

This is affecting the performance of some of the code pretty badly as every time it dumps something to kafka, there's a 1 second delay for every batch of data that gets written.

How to reproduce

Produce a message and poll until the ack arrives. I wrote a simple class to do this on cppkafka which you can use like this:

#include <chrono>
#include <cppkafka/utils/buffered_producer.h>

using namespace std;
using namespace std::chrono;
using namespace cppkafka;

int main() {
    Configuration config = {
        { "metadata.broker.list", "127.0.0.1:9092" }
    };

    // Create the producer
    BufferedProducer<string> producer(config);
    producer.get_producer().set_timeout(milliseconds(100));

    std::string payload = "payload!";
    producer.add_message("test" /*topic*/, 0 /*partition*/, payload);
    // This will actually wait for the message to be acked
    producer.flush();
}

Build and run (I'm using HEAD here):

matias@matias-laptop /tmp $ g++ kafka.cpp -o kafka -lcppkafka -lrdkafka -lsasl2 -lz -std=c++11
matias@matias-laptop /tmp $ ./kafka 
matias@matias-laptop /tmp $ time ./kafka 

real	0m1.126s
user	0m0.012s
sys	0m0.008s
matias@matias-laptop /tmp $ 

Now compare to when running this with v0.9.3

matias@matias-laptop /tmp $ time ./kafka 

real	0m0.147s
user	0m0.004s
sys	0m0.000s
matias@matias-laptop /tmp $ 

When using HEAD, this is the log output I get with debug: "all": https://gist.github.com/mfontanini/7c1c102b618a318088e5869b8bb36135. It seems like it waits one second until it actually produces the message?

Note that I modified my code in BufferedProducer and it seems like it's just polling multiple times waiting for the message to be sent, so it's not like it's getting blocked on poll. I also tried just calling poll and the timeout is respected, so it seems like it's specific to waiting for acks.

Checklist

Please provide the following information:

• librdkafka version (release number or git tag): >= v0.9.3
• Apache Kafka version: 0.10.1.0
• librdkafka client configuration: provided above
• Operating system: GNU/Linux
• Using the legacy Consumer
• Using the high-level KafkaConsumer
• Provide logs (with debug=.. as necessary) from librdkafka
• Provide broker log excerpts
• Critical issue

[edenhill]

Looks like queue.buffering.max.ms is doing what it should be doing then :)

https://github.com/edenhill/librdkafka/wiki/How-to-decrease-message-latency

[mfontanini]

Was this somehow only started being applied on 0.9.4? I see that configuration option has been there for months now.

[edenhill]

It was buggy before but fixed in 0.9.4

[mfontanini]

Oh okay. Closing then.