Kafka request.log中RequestQueueTimeMs、LocalTimeMs、RemoteTimeMs、ThrottleTimeMs、含义

Kafka request.log中RequestQueueTimeMs、LocalTimeMs、RemoteTimeMs、ThrottleTimeMs、含义

要理解各个延时项的含义，必须从Kafka收到TCP请求、处理请求到返回TCP包整个流程开始梳理

RequestQueueTimeMs

Processor 执行processNewResponses() 方法，不断 poll队列 得到socketchannel 拿到对应的client信息拼接connectionId 执行register(String id, SocketChannel socketChannel),注册Selector上，用于真正的请求获取和响应发送I/O操作

Processor 执行processCompletedReceives 从Selector中提取已接收到的所有请求数据， 如果有对应的socketchannel ，创建Requestnew RequestChannel.Request(processor = id, context = context,... 对象，添加到requestChannel的requestQueue中

override def run(): Unit = {
  startupComplete()
  try {
    while (isRunning) {
      try {
        //建立新链接
        configureNewConnections()
        //注册response写事件
        processNewResponses()
        poll()
        //简单理解成op_read事件
        processCompletedReceives()
        processCompletedSends()
        processDisconnected()
        closeExcessConnections()
      } catch {
        case e: Throwable => processException("Processor got uncaught exception.", e)
      }
    }
  } finally {
    debug(s"Closing selector - processor $id")
    CoreUtils.swallow(closeAll(), this, Level.ERROR)
    shutdownComplete()
  }
}

我们可以看到，在selector中当channel有数据可读时，会调用processCompletedReceives()方法，这个时候 startTimeNanos记录了当前时间

此时请求已经被封装为req，但是并没有真正的被处理，此时这个请求是被放入了requestQueue中，等待I/O线程进行处理。

KafkaRequestHandler时请求处理线程类，也是我们之前说的IO线程。每个请求处理线程实例，负责从 SocketServer 的 RequestChannel 的请求队列中获取请求对象，并进行处理。

所以如果RequestQueueTimeMs过高，说明请求进入requestQueue后由I/O线程取出时间过长，可以考虑增加IO线程数量。

LocalTimeMs

请求被取出后，会由KafkaApis中对应的方法进行处理

apis.handle(request)

在最后的finally方法中，记录了apiLocalCompleteTimeNanos

LocalTimeMs正是记录了request真正在broker中处理的时间，也就时本地的处理时间。如果这一步延时较长，需要根据请求类型（Fetch/Produce/OffsetCommit)请求的处理逻辑来分析究竟是哪一部分的具体逻辑导致处理超时了

RemoteTimeMs

val apiRemoteTimeMs = nanosToMs(responseCompleteTimeNanos - apiLocalCompleteTimeNanos)

在RequestTime的sendResponse方法中，我们看好了responseCompleteTime被记录了。

在生产环境中，我们经常会看到对于Fetch以及Produce请求，Remote Time可能会达到500ms左右，这是什么原因呢？

当Request被后面的I/O线程处理完成后，还要依靠Processor线程发送Response给请求方。但是要注意，有一些请求不是立即可以回复的，例如Produce请求（ack=-1）以及Fetch请求（设置了min.fetch.bytes/fetch.max.wait.ms)。当要求不被满足时，kafka通过时间轮来处理一些延时操作(例如DelayFetch等)

我们可以看到，当延时操作真正执行时时，sendResponse方法才会被调用。也就是说对于ack=-1的produce请求以及设置了min.fetch.bytes/fetch.max.wait.ms的Fetch请求（延时操作请求），RemoteTimeMs高的原因往往是可以返回相应的条件没有被满足；对于produce请求(ack=-1)，我们可以排查副本间同步的时延是不是比较高（broker间网络带宽）；对于Fetch请求，可能是消息不够多满足不了最小的拉取量，等待500ms返回

ThrottleTimeMs

这个指标项记录了请求被流控的时间，往往出现在做分区副本迁移时设置了流控或设置了client/user级别流控时。Kafka内置了一套软流控机制对请求的回包速度进行了限制。

如果这个指标较高，那么我们需要看看我们是否配置了相关的流控配置项

ResponseQueueTimeMs

当请求经过一系列处理后真正完成，会被封装为response。此时与request请求一样不会真正被发送，而是被放入到response队列中等待I/O线程取出

所以这里与RequestQueueTimeMs的意义类似，如果发现这个值比较高，可以可以考虑增加IO线程数量

ResponseSendTimeMs

当Processor将Response返回给Request发送方后，对于有些请求需要将其放入inflightResponses，也就是一个临时的Response队列中。这个队列存在的原因是Fetch/Produce请求的回调逻辑要在 Response 被发送回发送方之后，才能执行

用一个图来表示

如果ResponseSendTime较高，表示端到端的时延比较高，要对从broker->客户端以及客户端 ->broker整个链路上的网络问题进行排查（是不是网卡队列阻塞了，broker网络带宽达到瓶颈等）