KafkaProducerConnector producer.send() future call taking too much time
- Dominant language
- Scala
- Stars
- 6.8k
- Forks
- 1.2k
- Avg merge
- 2d 14h
- Merged PRs (30d)
- 2
Description
-->
## Environment details:
* I am using k8s setup on openwhisk-deploy-kube, with action limits increased to 99999 .
* One node hosts OW core components, the other node hosts the invoker
* Using the old scheduler, using a client generating request rate of around 100 rps, function take 0.02 seconds to complete ( all invoked with blocking calls)
* There are already 60 warm containers up and running before generating 100rps workload
* one controller and one invoker node both with 1024 Jvm heap
I found that requests formed a short queue when the controller schedules activation and posts the topic for invoker to consume
Here is an example log for a tid:
[2024-08-17T19:12:51.632Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ActionsApi] [marker:controller_blockingActivation_start:104]
[2024-08-17T19:12:51.632Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ActionsApi] action activation id: d3b7ed1f632b4bd1b7ed1f632b4bd101 [marker:controller_loadbalancer_start:104]
[2024-08-17T19:12:51.632Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ShardingContainerPoolBalancer] scheduled activation d3b7ed1f632b4bd1b7ed1f632b4bd101, action 'guest/aes@0.0.1' (managed), ns 'guest', mem limit 256 MB (std), time limit 60000 ms (std) to invoker0/owdev-invoker-0
[2024-08-17T19:12:51.632Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ShardingContainerPoolBalancer] posting topic 'invoker0' with activation id 'd3b7ed1f632b4bd1b7ed1f632b4bd101' [marker:controller_kafka_start:104]
[2024-08-17T19:12:51.666Z] [DEBUG] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [KafkaProducerConnector] sent message: invoker0[0][524]
[2024-08-17T19:12:51.666Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ShardingContainerPoolBalancer] posted to invoker0[0][524] [marker:controller_kafka_finish:122:18]
[2024-08-17T19:12:51.666Z] [INFO] [#tid_cbDR904isIhkDhBksSNU4GiocWngMPD1] [ActionsApi] [marker:controller_loadbalancer_finish:122:18]
The time between sent [ShardingContainerPoolBalancer] posting topic 'invoker0' and [KafkaProducerConnector] sent message: invoker0[0][524] is more than 30ms (there are cases when its more) and this results in many requests forming a queue here and subsequently a burst of jobs scheduled to invoker.
Upon inspecting source code in KafkaProducerConnector:
Future {
blocking {
try {
producer.send(record, new Callback {
override def onCompletion(metadata: RecordMetadata, exception: Exception): Unit = {
if (exception == null)
produced.trySuccess(ResultMetadata(metadata.topic(), metadata.partition(), metadata.offset()))
else produced.tryFailure(exception)
}
})
} catch {
case e: Throwable =>
produced.tryFailure(e)
}
}
}
produced.future.andThen {
case Success(status) =>
logging.debug(this, s"sent message: ${status.topic}[${status.partition}][${status.offset}]")
sentCounter.next()
case Failure(t) =>
logging.error(this, s"sending message on topic '$topic' failed: ${t.getMessage}")
Produced.future sucess is taking time. Upon checking logs more i found that messages invoker0[0][519-523] are sent in the meantime after the producer.send() with parititon 524 of and then finally invoker0[0][524] is sent. Why is the call and how can I increase performance here so that the short queue that forms does not happen because of the slow return of the future?
Contributor guide
Assessment
This issue has not been assessed yet.