FutureProducer::send observed duration is longer than publishing takes

[sukhmel]

Hello,

I have several independent tokio::mpsc channels producing messages that I then publish to Kafka. I'm trying to meter how long does it take for a FutureProducer to queue each message rec. Every message also contains its creation time to measure elapsed time on Kafka consumer side, too:

let timer: prometheus::HistogramTimer;
let producer: rdkafka::producer::FutureProducer;
/* … */
timer.start_timer()
let _ = producer
    .send(rec, Duration::from_secs(0))
    .await;
timer.observe_duration();

I observe several effects:

1. When I measure time from rec creation to rec consumption, this time is < 1 second
2. Average wait on this timer is ≈ 0.3 seconds
3. Median wait is ≈ 3 seconds
4. 95 percentile is ≈ 9 seconds

My speculation is as follows: observed "lag" is different from the real because FutureProducer sends request to queue the message into librdkafka and then uses await to give control somewhere else until eventually it is awakened to observe that queueing is completed. In my case messages come from separate channels, and sometimes the future is only polled once the next message comes, by which time everything is long published to Kafka, but we didn't bother to check.

I am not sure if my understanding is correct. Initially I interpreted this part of send doc: "parameter controls how long to retry for if the librdkafka producer queue is full" to mean that the FutureProducer::send will always take less time than the actual publishing even if polled late, but I suspect that's more complicated than that and can't quite figure out, how.

[sukhmel]

It appears, the issue was with how I plotted the measurements. When plotted correctly, both measured kafka write duration, and time before client read look very similar. For posterity, problem was that I had written sum by(origin) (histogram_quantile(0.5, rate(…))) instead of histogram_quantile(0.5, sum by(origin, le) (rate(…)))

I will now close the question as answered, if anyone has some more insight into how FutureProducer can be (mis)measured, please add to the thread.

[sukhmel]

I must note that after fixing the metrics FutureProducer::send still shows longer times than message lifetime, only about 200ms less. Maybe that's just a discrepancy in the clock between the reader and the writer.

[testinfected]

@sukhmel I have a similar setup with a probe that monitors my Kafka and sends/receives ping messages. To measure the send time only, I use the stats provided by librdkafka (see https://github.com/confluentinc/librdkafka/blob/master/STATISTICS.md).

They are available in your Rust code creating your producer with a context (see https://docs.rs/rdkafka/latest/rdkafka/statistics/index.html). I guess you're interested in broker rtt stat here