Confluent-kafka-dotnet: Slow manual commits

Created on 6 Feb 2018  路  40Comments  路  Source: confluentinc/confluent-kafka-dotnet

Description

We need to expose manual sync commits to our clients, but we get really poor performance out of it when compared to async commits + callbacks.

Attached client logs with "debug: all" for sync and async versions.
sync_commit.txt
async_commit.txt

How to reproduce

It looks like the commit request itself is quite quick but between the request being enqueued and sent to the broker it can take a while (~1sec) and I can see quite a few FetchRequests in between commits even though the flow of our consumer is something like:

private Message<string, byte[]> ConsumeMessageSync()
{
    Message<string, byte[]> kafkaMessage;
    _consumer.Consume(out kafkaMessage, 100);  
    return kafkaMessage;
}

var msg = ConsumeMessageSync();
var clientReadyMsg = process(msg);
emitMessageToClient(clientReadyMsg);

then client subscribes and commits after each emission...

What I don't understand is why fetch requests are issued to the broker after the commit request is enqueued and while we wait for the commit result to come back. I played around with fetch.wait.max.ms but that just changes the amount of fetch requests that gets sent in between.

Additionally there are some weird PROTOERR level messages like this:

7|2018-02-06 12:01:01.765|rdkafka#consumer-1|PROTOERR| [thrd:lonrs08346.my-domain.net:2182/bootstrap]: lonrs08346.my-domain.net:2182/2: Protocol parse failure at 1048332/1048648 (rd_kafka_msgset_reader_msg_v0_1:464) (incorrect broker.version.fallback?)

Probably not related but worth pointing out. Is there something I am missing? Thanks in advance!

Checklist

Please provide the following information:

  • [x] Confluent.Kafka nuget version: 0.11.3
  • [x] Apache Kafka version: 0.10.0.1
  • [x] Client configuration:
    {"enable.auto.commit", "false"},
    {"auto.offset.reset", "earliest"}
  • [x] Operating system: Win7x64
  • [x] Provide logs (with "debug" : "..." as necessary in configuration)
  • [ ] Provide broker log excerpts
  • [x] Critical issue

sync_commit.txt
async_commit.txt

HIGH bug librdkafka
Source
picture ricardoecosta
👍1

Most helpful comment

Thank you all for your patience.

I've now identified the issue:
https://github.com/edenhill/librdkafka/blob/master/src/rdkafka_broker.c#L3187

When committing to a broker that we're not fetching messages from there is a high probability that queued ops (such as a Commit) will be delayed up to 1000ms before being sent, regardless of socket.blocking.max.ms.

I have a fix in place which I'll test and then commit to master.

There is no workaround.

librdkafka issue: https://github.com/edenhill/librdkafka/issues/1787

picture edenhill on 27 Apr 2018
👍2

All 40 comments

https://github.com/edenhill/librdkafka/wiki/FAQ#sync-offset-commits-are-slow

re the PROTOERR; are you seeing that without debug enabled?

edenhill picture edenhill on 6 Feb 2018

Hi Magnus, thanks for the quick reply!

I did have look to that page and I decreased fetch.wait.max.ms but the side effect of that is the number of fetch requests being increased:

06/02/2018 13:30:33 -> Committed7|2018-02-06 13:30:33.581|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1477, rtt 16.00ms)
7|2018-02-06 13:30:33.581|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1478)
7|2018-02-06 13:30:33.599|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1478, rtt 31.00ms)
7|2018-02-06 13:30:33.599|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1479)
7|2018-02-06 13:30:33.617|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1479, rtt 16.00ms)
7|2018-02-06 13:30:33.617|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1480)
7|2018-02-06 13:30:33.635|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1480, rtt 15.00ms)
7|2018-02-06 13:30:33.635|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1481)
7|2018-02-06 13:30:33.653|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1481, rtt 16.00ms)
7|2018-02-06 13:30:33.653|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1482)
7|2018-02-06 13:30:33.671|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1482, rtt 15.00ms)
7|2018-02-06 13:30:33.672|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1483)
7|2018-02-06 13:30:33.689|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1483, rtt 16.00ms)
7|2018-02-06 13:30:33.690|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1484)
7|2018-02-06 13:30:33.708|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1484, rtt 31.00ms)
7|2018-02-06 13:30:33.708|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1485)
7|2018-02-06 13:30:33.727|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1485, rtt 16.00ms)
7|2018-02-06 13:30:33.728|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1486)
7|2018-02-06 13:30:33.746|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1486, rtt 15.00ms)
7|2018-02-06 13:30:33.746|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1487)
7|2018-02-06 13:30:33.764|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1487, rtt 16.00ms)
7|2018-02-06 13:30:33.764|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1488)
7|2018-02-06 13:30:33.782|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1488, rtt 16.00ms)
7|2018-02-06 13:30:33.782|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1489)
7|2018-02-06 13:30:33.800|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1489, rtt 31.00ms)
7|2018-02-06 13:30:33.801|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1490)
7|2018-02-06 13:30:33.819|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1490, rtt 15.00ms)
7|2018-02-06 13:30:33.819|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1491)
7|2018-02-06 13:30:33.837|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1491, rtt 16.00ms)
7|2018-02-06 13:30:33.837|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1492)
7|2018-02-06 13:30:33.855|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1492, rtt 16.00ms)
7|2018-02-06 13:30:33.855|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1493)
7|2018-02-06 13:30:33.873|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1493, rtt 15.00ms)
7|2018-02-06 13:30:33.873|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1494)
7|2018-02-06 13:30:33.891|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1494, rtt 16.00ms)
7|2018-02-06 13:30:33.892|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1495)
7|2018-02-06 13:30:33.910|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1495, rtt 31.00ms)
7|2018-02-06 13:30:33.910|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1496)
7|2018-02-06 13:30:33.928|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1496, rtt 16.00ms)
7|2018-02-06 13:30:33.928|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1497)
7|2018-02-06 13:30:33.946|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1497, rtt 15.00ms)
7|2018-02-06 13:30:33.946|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1498)
7|2018-02-06 13:30:33.964|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1498, rtt 16.00ms)
7|2018-02-06 13:30:33.964|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1499)
7|2018-02-06 13:30:33.982|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1499, rtt 15.00ms)
7|2018-02-06 13:30:33.982|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1500)
7|2018-02-06 13:30:33.999|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1500, rtt 16.00ms)
7|2018-02-06 13:30:34.000|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1501)
7|2018-02-06 13:30:34.018|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1501, rtt 16.00ms)
7|2018-02-06 13:30:34.018|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1502)
7|2018-02-06 13:30:34.036|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1502, rtt 31.00ms)
7|2018-02-06 13:30:34.037|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1503)
7|2018-02-06 13:30:34.055|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1503, rtt 15.00ms)
7|2018-02-06 13:30:34.055|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1504)
7|2018-02-06 13:30:34.073|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1504, rtt 16.00ms)
7|2018-02-06 13:30:34.073|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1505)
7|2018-02-06 13:30:34.091|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1505, rtt 16.00ms)
7|2018-02-06 13:30:34.093|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1506)
7|2018-02-06 13:30:34.111|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1506, rtt 15.00ms)
7|2018-02-06 13:30:34.111|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1507)
7|2018-02-06 13:30:34.129|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1507, rtt 31.00ms)
7|2018-02-06 13:30:34.129|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1508)
7|2018-02-06 13:30:34.147|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1508, rtt 16.00ms)
7|2018-02-06 13:30:34.147|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1509)
7|2018-02-06 13:30:34.165|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1509, rtt 16.00ms)
7|2018-02-06 13:30:34.166|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1510)
7|2018-02-06 13:30:34.183|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1510, rtt 15.00ms)
7|2018-02-06 13:30:34.184|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1511)
7|2018-02-06 13:30:34.202|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1511, rtt 16.00ms)
7|2018-02-06 13:30:34.202|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1512)
7|2018-02-06 13:30:34.220|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1512, rtt 15.00ms)
7|2018-02-06 13:30:34.220|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1513)
7|2018-02-06 13:30:34.238|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1513, rtt 32.00ms)
7|2018-02-06 13:30:34.238|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1514)
7|2018-02-06 13:30:34.256|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1514, rtt 15.00ms)
7|2018-02-06 13:30:34.256|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1515)
7|2018-02-06 13:30:34.275|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1515, rtt 16.00ms)
7|2018-02-06 13:30:34.276|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1516)
7|2018-02-06 13:30:34.293|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1516, rtt 15.00ms)
7|2018-02-06 13:30:34.294|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1517)
7|2018-02-06 13:30:34.312|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1517, rtt 16.00ms)
7|2018-02-06 13:30:34.312|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1518)
7|2018-02-06 13:30:34.330|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1518, rtt 16.00ms)
7|2018-02-06 13:30:34.330|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1519)
7|2018-02-06 13:30:34.348|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1519, rtt 31.00ms)
7|2018-02-06 13:30:34.348|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1520)
7|2018-02-06 13:30:34.366|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1520, rtt 15.00ms)
7|2018-02-06 13:30:34.366|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1521)
7|2018-02-06 13:30:34.384|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1521, rtt 16.00ms)
7|2018-02-06 13:30:34.384|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1522)
7|2018-02-06 13:30:34.402|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1522, rtt 16.00ms)
7|2018-02-06 13:30:34.402|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1523)
7|2018-02-06 13:30:34.420|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1523, rtt 15.00ms)
7|2018-02-06 13:30:34.420|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1524)
7|2018-02-06 13:30:34.438|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1524, rtt 16.00ms)
7|2018-02-06 13:30:34.438|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1525)
7|2018-02-06 13:30:34.455|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1525, rtt 31.00ms)
7|2018-02-06 13:30:34.456|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1526)
7|2018-02-06 13:30:34.474|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1526, rtt 16.00ms)
7|2018-02-06 13:30:34.474|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1527)
7|2018-02-06 13:30:34.492|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1527, rtt 15.00ms)
7|2018-02-06 13:30:34.493|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1528)
7|2018-02-06 13:30:34.510|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1528, rtt 16.00ms)
7|2018-02-06 13:30:34.511|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1529)
7|2018-02-06 13:30:34.529|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1529, rtt 15.00ms)
7|2018-02-06 13:30:34.529|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1530)
7|2018-02-06 13:30:34.547|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1530, rtt 16.00ms)
7|2018-02-06 13:30:34.547|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1531)
7|2018-02-06 13:30:34.565|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1531, rtt 31.00ms)
7|2018-02-06 13:30:34.565|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1532)
7|2018-02-06 13:30:34.574|rdkafka#consumer-1|SEND| [thrd:foobar08766.my-domain.net:2182/bootstrap]: foobar08766.my-domain.net:2182/3: Sent OffsetCommitRequest (v1, 194 bytes @ 0, CorrId 37)
7|2018-02-06 13:30:34.574|rdkafka#consumer-1|SEND| [thrd:foobar08766.my-domain.net:2182/bootstrap]: foobar08766.my-domain.net:2182/3: Sent HeartbeatRequest (v0, 122 bytes @ 0, CorrId 38)
7|2018-02-06 13:30:34.583|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1532, rtt 16.00ms)
7|2018-02-06 13:30:34.583|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1533)
7|2018-02-06 13:30:34.601|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1533, rtt 15.00ms)
7|2018-02-06 13:30:34.601|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1534)
7|2018-02-06 13:30:34.619|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received FetchResponse (v2, 72 bytes, CorrId 1534, rtt 16.00ms)
7|2018-02-06 13:30:34.620|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent FetchRequest (v2, 99 bytes @ 0, CorrId 1535)
7|2018-02-06 13:30:34.629|rdkafka#consumer-1|RECV| [thrd:foobar08766.my-domain.net:2182/bootstrap]: foobar08766.my-domain.net:2182/3: Received OffsetCommitResponse (v1, 56 bytes, CorrId 37, rtt 63.00ms)
7|2018-02-06 13:30:34.630|rdkafka#consumer-1|RECV| [thrd:foobar08766.my-domain.net:2182/bootstrap]: foobar08766.my-domain.net:2182/3: Received HeartbeatResponse (v0, 2 bytes, CorrId 38, rtt 63.00ms)
06/02/2018 13:30:34 -> Committed

Regarding the PROTOERR it doesn't happen with debug disabled.

ricardoecosta picture ricardoecosta on 6 Feb 2018

Okay, then that PROTOERR can be ignored, it is expected.

It seems like there are no FetchRequest blocking the OffsetCommitRequest, which means the latency of that request (63ms) is due to the network and broker processing time.

edenhill picture edenhill on 6 Feb 2018

If you kindly look at sync_commit.txt and search for Enqueue OffsetCommitRequest that's when the commit request is issued:

7|2018-02-06 12:01:01.826|rdkafka#consumer-1|OFFSET| [thrd:main]: lonrs08043.my-domain.net:2182/1: Enqueue OffsetCommitRequest(v1, 1/1 partition(s))): manual

but then it only gets sent to the broker almost after a second:

7|2018-02-06 12:01:02.784|rdkafka#consumer-1|SEND| [thrd:lonrs08043.my-domain.net:2182/bootstrap]: lonrs08043.my-domain.net:2182/1: Sent OffsetCommitRequest (v1, 194 bytes @ 0, CorrId 9)

Do you have any idea what all those FetchRequests are? Shouldn't they only be sent on consumer.Consume/Poll?

ricardoecosta picture ricardoecosta on 6 Feb 2018

The client pre-fetches messages in the background until queued.min.messages or queued.max.messages.kbytes is reached at which time it will stop fetching until those thresholds are no longer reached.

If there are no new messages on the broker the FetchRequest will block (on the broker) up to fetch.wait.max.ms and any sub-sequently sent requests, such as an OffsetCommitRequest, will be blocked until the Fetch completes.

edenhill picture edenhill on 6 Feb 2018

Looked at the sync_commit.txt and it indeed blocks for 1s:
On Windows you might need to speed up internal wakeups by setting socket.blocking.max.ms to a lower value, such as 10.

edenhill picture edenhill on 6 Feb 2018

I actually had played around with those before as well but unfortunately didn't help, I made another test just now and for the following settings:

                {"fetch.wait.max.ms", 100},
                {"socket.blocking.max.ms", 10},
                {"queued.max.messages.kbytes", 1024},
                {"heartbeat.interval.ms", 10000},

...idea being minimize the amount of pre-fetches and heartbeats, I get 2 following behaviours:

  1. A slow consumer where it blocks for 1 second between these following highlighted lines:
2018-02-06 14:47:30,003 [1] [Test.foo] [(null)] INFO  D.N.D.fooKafkaConsumer`1 - Polling
7|2018-02-06 14:47:30.003|rdkafka#consumer-1|CGRPOP| [thrd:main]: Group "default-group0b8abc27-f879-4789-9424-99fa1a1c5d1e" received op OFFSET_COMMIT (v0) in state up (join state started, v4 vs 0)
==> 7|2018-02-06 14:47:30.003|rdkafka#consumer-1|OFFSET| [thrd:main]: foobar08043.my-domain.net:2182/1: Enqueue OffsetCommitRequest(v1, 1/1 partition(s))): manual
==> 7|2018-02-06 14:47:31.002|rdkafka#consumer-1|SEND| [thrd:foobar08043.my-domain.net:2182/bootstrap]: foobar08043.my-domain.net:2182/1: Sent OffsetCommitRequest (v1, 194 bytes @ 0, CorrId 9)
7|2018-02-06 14:47:31.057|rdkafka#consumer-1|RECV| [thrd:foobar08043.my-domain.net:2182/bootstrap]: foobar08043.my-domain.net:2182/1: Received OffsetCommitResponse (v1, 56 bytes, CorrId 9, rtt 62.00ms)
7|2018-02-06 14:47:31.058|rdkafka#consumer-1|COMMIT| [thrd:main]: foobar08043.my-domain.net:2182/1: OffsetCommit for 1 partition(s): manual: returned: Success
2018-02-06 14:47:31,058 [18] [(null)] [(null)] INFO  D.N.D.fooKafkaConsumer`1 - Committed
  1. A fast consumer (always a fast consumer when the assigned coordinator is the leader of the topic partition):
2018-02-06 14:46:20,059 [1] [Test.foo] [(null)] INFO  D.N.D.fooKafkaConsumer`1 - Polling
7|2018-02-06 14:46:20.060|rdkafka#consumer-1|CGRPOP| [thrd:main]: Group "default-group90071a46-7ad7-439a-aaf1-274123f93588" received op OFFSET_COMMIT (v0) in state up (join state started, v4 vs 0)
==> 7|2018-02-06 14:46:20.060|rdkafka#consumer-1|OFFSET| [thrd:main]: foobar08346.my-domain.net:2182/2: Enqueue OffsetCommitRequest(v1, 1/1 partition(s))): manual
==> 7|2018-02-06 14:46:20.068|rdkafka#consumer-1|SEND| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Sent OffsetCommitRequest (v1, 194 bytes @ 0, CorrId 63)
7|2018-02-06 14:46:20.129|rdkafka#consumer-1|RECV| [thrd:foobar08346.my-domain.net:2182/bootstrap]: foobar08346.my-domain.net:2182/2: Received OffsetCommitResponse (v1, 56 bytes, CorrId 63, rtt 63.00ms)
7|2018-02-06 14:46:20.129|rdkafka#consumer-1|COMMIT| [thrd:main]: foobar08346.my-domain.net:2182/2: OffsetCommit for 1 partition(s): manual: returned: Success
2018-02-06 14:46:20,130 [18] [(null)] [(null)] INFO  D.N.D.fooKafkaConsumer`1 - Committed

Additionally I forgot to mention that we have a java client as well, which doesn't have these issues (just to rule out environment problems).

ricardoecosta picture ricardoecosta on 6 Feb 2018

Thanks for that bit of information, I'll try to reproduce it and see if we can find a proper fix.

edenhill picture edenhill on 6 Feb 2018
👍1

Any luck so far?

ricardoecosta picture ricardoecosta on 8 Feb 2018

@edenhill have you had a chance to look at the issue? Let me know if I can help in any way.

ricardoecosta picture ricardoecosta on 13 Feb 2018

I modified examples/rdkafka_consumer_example.cpp to call commitSync() on each consumed message here:
https://github.com/edenhill/librdkafka/blob/master/examples/rdkafka_consumer_example.cpp#L457

But there is no delay, it commits instantly.

edenhill picture edenhill on 13 Feb 2018

I can add to it. I am having same issue.

However it is related to cluster setup. That being said, it depends on which of brokers your topic is master on. In my particular case where I am having same issue with 1 second commits, we have 3 brokers & every third created consumer group performs fairly quick commits (less than 100 ms).

So to reproduce it you will need 3 brokers cluster, then create single topic with one partition push some messages to it. Then create three different consumers with different consumer groups on same topic one after another. One of these consumers will have fairly quick commit while other will have 1 second like commits.

I think it is directly related to which broker owns topic as master.

Please try to investigate this and reproduce under mentioned conditions. We are currently are ok with 1 second commits but with increasing load we'll be forced to move to other MQ solution which I do not want to as I really enjoy Kafka.

KarolisKaj picture KarolisKaj on 14 Feb 2018

Thanks @KarolisKaj, it looks like we both are seeing the same issue indeed: I also have a setup with 3 brokers and only one fast consumer every ~3 times and, as I said before, I pinpointed this to when the assigned coordinator is the leader of the topic partition.

@edenhill one second commits are not acceptable at all for us, even if we committed every 3k messages or so, there must be something going on? Perhaps trying to replicate the same environment with the C# client will maximize the chances of you replicating the issue.

ricardoecosta picture ricardoecosta on 14 Feb 2018

@edenhill - if you haven't already, please take a look at the C# implementation of commitSync and confirm (or not) that this is appropriate use of the librdkafka API. https://github.com/confluentinc/confluent-kafka-dotnet/blob/master/src/Confluent.Kafka/Impl/SafeKafkaHandle.cs#L566

if that all looks good to you, I'll attempt to reproduce.

mhowlett picture mhowlett on 15 Feb 2018

@mhowlett looks good

edenhill picture edenhill on 15 Feb 2018
👍1

@ricardoecosta , @KarolisKaj - in the below, if tt2 is a topic on a 3 broker cluster with a single partition, replication factor 3, does this match your scenario? (I am not seeing slow commits, using kafka broker version 1 though). sorry if i'm mis-interpreting, just had a quick look at this point.

using System;
using System.Collections.Generic;
using System.Text;
using System.Threading.Tasks;
using Confluent.Kafka;
using Confluent.Kafka.Serialization;

namespace testcommit
{
    class Program
    {
        static void TestCommitLatency(int id)
        {
            var conf = new Dictionary<string, object>
            {
                { "bootstrap.servers", "localhost:9093" },
                { "group.id", new Guid().ToString() }
            };

            using (var consumer = new Consumer<Null, string>(conf, null, new StringDeserializer(Encoding.UTF8)))
            {
                consumer.Assign(new List<TopicPartitionOffset> { new TopicPartitionOffset("tt2", 0, 0) });

                while (true)
                {
                    if (consumer.Consume(out Message<Null, string> msg, TimeSpan.FromSeconds(1)))
                    {
                        var startTime = DateTime.Now;
                        var r = consumer.CommitAsync().Result;
                        Console.WriteLine($"{id}: {r.Error.Reason}, commit milliseconds: {(DateTime.Now - startTime).TotalMilliseconds}");
                    }
                    else 
                    {
                        Console.WriteLine($"{id}: no msg.");
                    }
                }
            }
        }

        static void Main(string[] args)
        {
            var conf = new Dictionary<string, object>
            {
                { "bootstrap.servers", "localhost:9093" }
            };

            using (var producer = new Producer<Null, string>(conf, null, new StringSerializer(Encoding.UTF8)))
            {
                for (int i=0; i<100000; ++i)
                {
                    producer.ProduceAsync("tt2", null, "sdf");
                }

                Console.WriteLine(producer.Flush(10000));
            }

            Task.Run(() => TestCommitLatency(1));
            Task.Run(() => TestCommitLatency(2));
            Task.Run(() => TestCommitLatency(3));

            Task.Delay(TimeSpan.FromDays(1)).Wait();
        }
    }
}
mhowlett picture mhowlett on 15 Feb 2018

@mhowlett Thanks for your client demo.

Here is my results:
image

Only thing I have changed was hosts as such:
{ "bootstrap.servers", "Y31489,Y31490,Y31491" }

Attaching our Zookeeper & Kafka configs:
configs.zip

Please let me know if there are any difference from your setup. Thanks in advance.

KarolisKaj picture KarolisKaj on 15 Feb 2018

My results:

1: Success, commit milliseconds: 226.0226
3: Success, commit milliseconds: 232.0232
1: Success, commit milliseconds: 246.0246
2: Success, commit milliseconds: 346.0346
3: Success, commit milliseconds: 245.0245
1: Success, commit milliseconds: 233.0233
2: Success, commit milliseconds: 236.0236
3: Success, commit milliseconds: 266.0266
2: Success, commit milliseconds: 125.0125
1: Success, commit milliseconds: 1009.1009
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1009.1009
1: Success, commit milliseconds: 1007.1007
1: Success, commit milliseconds: 15.0015
3: Success, commit milliseconds: 1008.1008
3: Success, commit milliseconds: 17.0017
2: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 17.0017
1: Success, commit milliseconds: 1008.1008
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1008.1008
1: Success, commit milliseconds: 1007.1007
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1008.1008
1: Success, commit milliseconds: 1007.1007
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1008.1008
1: Success, commit milliseconds: 1008.1008
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1008.1008
1: Success, commit milliseconds: 1008.1008
1: Success, commit milliseconds: 15.0015
3: Success, commit milliseconds: 1008.1008
3: Success, commit milliseconds: 17.0017
2: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 17.0017
1: Success, commit milliseconds: 1008.1008
3: Success, commit milliseconds: 1008.1008
2: Success, commit milliseconds: 1008.1008

@mhowlett are you testing in windows?

ricardoecosta picture ricardoecosta on 15 Feb 2018

I was using osx, getting typically ~0.3ms commits. On windows (.net core and .net framework) I'm seeing ~1000ms commits. This pretty conclusively points to librdkafka I think. It's interesting that the number is so close to 1000, seems likely to me that is indicative of something. @edenhill

mhowlett picture mhowlett on 15 Feb 2018

Try lowering socket.blocking.max.ms

edenhill picture edenhill on 15 Feb 2018

no difference. also, lowering broker.address.ttl and heartbeat.interval.ms makes no difference (i wouldn't expect they would, but they have default value 1000 so worth a quick test).

mhowlett picture mhowlett on 15 Feb 2018

@mhowlett that was also my thinking and played around with those before, anyway good to have confirmation, thanks.

ricardoecosta picture ricardoecosta on 15 Feb 2018

I also just checked to see if a more recent build of librdkafka resolves the issue (referenced by Confluent.Kafka 0.11.3-ci-280), no luck. I expect to get a chance to delve in to debugging librdkafka later this week or early next week.

mhowlett picture mhowlett on 15 Feb 2018
👍2

currently a bit swamped, haven't forgotten about this, somewhere near the top of the priority list ...

mhowlett picture mhowlett on 22 Feb 2018
👍2

@mhowlett any prediction when you will have time to look at this?

ricardoecosta picture ricardoecosta on 12 Mar 2018

sorry for the delay. if we can't get this into the 0.11.4 release, i'll make sure we do a CI build with it in soon after.

mhowlett picture mhowlett on 12 Mar 2018
👍1

Does that mean you found the cause of the issue?

ricardoecosta picture ricardoecosta on 14 Mar 2018
👍1

I have not yet looked tbh. I mentioned this bug to @edenhill again yesterday and he commented that he thought it's likely related to and would get automatically fixed by some upcoming work happening in librdkafka. he may like to comment further here.

mhowlett picture mhowlett on 14 Mar 2018
👍2

@mhowlett Thanks for your efforts thus far, please update us when possible fix is available :)

KarolisKaj picture KarolisKaj on 15 Mar 2018
👍1

@edenhill sorry for pushing on this yet again but this is blocking us for quite a while now, how long do you think this is gonna take? otherwise we may have to think about alternative solutions, or maybe I can help somehow?

ricardoecosta picture ricardoecosta on 22 Mar 2018

@ricardoecosta Sorry for the delay, we're currently in the late stages of the release cycles and bogged down with verification tests and other release tasks, so there is very little bandwidth right now but we will look into this as soon the releases are out.

One way to help would be to provide a minimal reproducible test case program.

edenhill picture edenhill on 22 Mar 2018

@edenhill you can use the test program posted by @mhowlett up there, the key to reproduce it was running it on windows. When is the next release out?

ricardoecosta picture ricardoecosta on 27 Mar 2018
👍1

I am encountering the same issue. However, when I'm running the .NET client against the confluent kafka Docker image (single node), I don't experience this issue. I'm using version 0.11.4 of the Confluent.Kafka NuGet package. I'm running against the latest (4.0) confluent-kafka-2.11 yum package on CentOS 7.3 using the default configuration (3 nodes).

To work around this issue, I've modified my code to not await the Consumer.CommitAsync() call and add a .ContinueWith() to handle commit completion and errors. In doing this, I'm processing messages as fast as I would expect. However, I'm not sure what to do if CommitAsync() throws an exception or returns an error in the CommittedOffsets result object. Previously when the CommittedOffsets result had a non-success error code, we were simply disposing of the Consumer object and starting over.

GarrettDavis picture GarrettDavis on 6 Apr 2018

@GarrettDavis - If you have a scenario in which awaiting the CommitAsync call is useful, i'd be interested in some knowing more details. I started to regret not just making this a synchronous method, since I believe this reflects how most people would want to use it + behind the scenes it just wraps a synchronous call in a thread pool thread. We're considering switching this in the 1.0 release.

sorry we haven't got to debugging this yet. I think magnus was speculating that some other changes he wants to do may fix this as a side effect.

mhowlett picture mhowlett on 6 Apr 2018
👍2

@mhowlett I would suggest making it a just synchronous call because that's what it is. I would leave it up to the consumers of this library whether or not they want to wrap it in a Task.Run() or offload it onto another thread. In order to avoid making this a breaking change, you could implement a CommitAsync(this Consumer consumer, ...) extension method that wraps the synchronous Consumer.Commit() in a Task.Run(). Of course, since it's a major release, it's OK to make a breaking change.

GarrettDavis picture GarrettDavis on 9 Apr 2018
👍2

Hi, can we make sure we keep this thread about manual sync commits? Offloading commits to different thread is not an option for our use case and I imagine there's more people wanting to do the same. Though I agree with the proposals for the API change, I think it makes sense.

ricardoecosta picture ricardoecosta on 13 Apr 2018

@mhowlett @edenhill is it realistic to expect news on this soon?

ricardoecosta picture ricardoecosta on 27 Apr 2018

Thank you all for your patience.

I've now identified the issue:
https://github.com/edenhill/librdkafka/blob/master/src/rdkafka_broker.c#L3187

When committing to a broker that we're not fetching messages from there is a high probability that queued ops (such as a Commit) will be delayed up to 1000ms before being sent, regardless of socket.blocking.max.ms.

I have a fix in place which I'll test and then commit to master.

There is no workaround.

librdkafka issue: https://github.com/edenhill/librdkafka/issues/1787

edenhill picture edenhill on 27 Apr 2018
👍2

Is this issue still open? I'm having ~1000ms latency between sending a message and receiving it:

lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 18.04.4 LTS
Release:    18.04
Codename:   bionic

uname -r
5.3.0-40-generic

Confluent.Kafka nuget version 1.4.0-RC2

Have got some simplistic sample code to reproduce the issue if needed.

TrevorDArcyEvans picture TrevorDArcyEvans on 2 Mar 2020

yep, resolved by: https://github.com/edenhill/librdkafka/issues/1930
also, it was a windows only issue.

please open a new issue and paste code - thanks!

mhowlett picture mhowlett on 2 Mar 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Duorman picture Duorman  路  3Comments
ThomasHjorslevFcn picture ThomasHjorslevFcn  路  3Comments
ietvijay picture ietvijay  路  3Comments
keggster101020 picture keggster101020  路  4Comments
alfhv picture alfhv  路  3Comments