[ https://issues.apache.org/jira/browse/KAFKA-666?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Neha Narkhede resolved KAFKA-666. --------------------------------- Resolution: Incomplete Fix Version/s: (was: 0.8.1) Need more information to understand the issue > Fetch requests from the replicas take several seconds to complete on the > leader > ------------------------------------------------------------------------------- > > Key: KAFKA-666 > URL: https://issues.apache.org/jira/browse/KAFKA-666 > Project: Kafka > Issue Type: Bug > Affects Versions: 0.8.0 > Reporter: Neha Narkhede > Priority: Critical > Labels: replication-performance > > I've seen that fetch requests from the replicas take several seconds to > complete. The nature of the latency breakdown is different, sometimes they > spend too long sitting in the request/response queue, sometimes the > local/remote time is too large - > [2012-12-07 20:14:51,233] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.45-port_9092: FetchRequest:9967, > queueTime:0, localTime:4, remoteTime:9963, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 20:14:51,236] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.45-port_9092: FetchRequest:9967, > queueTime:1, localTime:3, remoteTime:9963, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 20:14:51,239] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.45-port_9092: FetchRequest:9966, > queueTime:0, localTime:2, remoteTime:9964, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 20:16:07,643] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.45-port_9092: FetchRequest:9996, > queueTime:1, localTime:2, remoteTime:9992, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 20:16:07,645] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.45-port_9092: FetchRequest:9999, > queueTime:0, localTime:4, remoteTime:9994, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 20:59:22,424] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3502, > queueTime:1, localTime:1, remoteTime:3500, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:13:35,042] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3981, > queueTime:0, localTime:1, remoteTime:3979, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:13:35,042] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4095, > queueTime:1, localTime:6, remoteTime:4088, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:13:57,254] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4116, > queueTime:1, localTime:1, remoteTime:4113, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:13:57,300] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3844, > queueTime:1, localTime:3795, remoteTime:48, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:14:19,645] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4239, > queueTime:1, localTime:1, remoteTime:4236, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:14:19,689] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3977, > queueTime:3931, localTime:8, remoteTime:38, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:23:58,427] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3940, > queueTime:1, localTime:1, remoteTime:3938, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:23:58,435] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3858, > queueTime:1, localTime:6, remoteTime:3851, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:24:21,575] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4037, > queueTime:0, localTime:1, remoteTime:4036, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:24:21,583] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3962, > queueTime:1, localTime:4, remoteTime:3956, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:24:43,965] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4294, > queueTime:1, localTime:1, remoteTime:4292, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:24:44,013] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3962, > queueTime:1, localTime:3919, remoteTime:41, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:06,157] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4587, > queueTime:1, localTime:1, remoteTime:4585, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:06,162] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4276, > queueTime:1, localTime:6, remoteTime:4268, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:28,943] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3986, > queueTime:1, localTime:1, remoteTime:3984, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:28,953] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3940, > queueTime:3929, localTime:6, remoteTime:5, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:51,374] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4319, > queueTime:0, localTime:1, remoteTime:4318, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:25:51,374] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4328, > queueTime:1, localTime:6, remoteTime:4320, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:13,934] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3949, > queueTime:0, localTime:1, remoteTime:3948, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:13,934] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4412, > queueTime:1, localTime:6, remoteTime:4404, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:36,268] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4227, > queueTime:0, localTime:2, remoteTime:4224, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:36,268] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4573, > queueTime:1, localTime:6, remoteTime:4565, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:59,503] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3996, > queueTime:0, localTime:2, remoteTime:3994, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:26:59,504] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4457, > queueTime:1, localTime:4, remoteTime:504, sendTime:3948 > (kafka.network.RequestChannel$) > [2012-12-07 21:27:21,624] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4010, > queueTime:0, localTime:1, remoteTime:4009, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:27:21,704] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4036, > queueTime:3955, localTime:8, remoteTime:72, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:27:42,374] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4429, > queueTime:1, localTime:1, remoteTime:4427, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:27:42,381] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4290, > queueTime:1, localTime:4, remoteTime:4284, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:28:03,198] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4229, > queueTime:0, localTime:1, remoteTime:4228, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:28:25,540] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4054, > queueTime:1, localTime:1, remoteTime:4052, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:28:25,540] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4203, > queueTime:1, localTime:5, remoteTime:4196, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:28:45,923] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4289, > queueTime:0, localTime:1, remoteTime:4288, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:28:45,930] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4004, > queueTime:1, localTime:4002, remoteTime:0, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:29:07,457] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4438, > queueTime:0, localTime:1, remoteTime:4436, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:29:07,463] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4028, > queueTime:1, localTime:6, remoteTime:4020, sendTime:1 > (kafka.network.RequestChannel$) > [2012-12-07 21:29:29,017] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4463, > queueTime:0, localTime:1, remoteTime:4462, sendTime:0 > (kafka.network.RequestChannel$) > [2012-12-07 21:29:29,018] TRACE Completed request with correlation id 0 and > client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:4524, > queueTime:1, localTime:6, remoteTime:4515, sendTime:2 > (kafka.network.RequestChannel$) > This is probably a performance issue in the replica fetch code path on the > leader -- This message was sent by Atlassian JIRA (v6.1.5#6160)