Neha Narkhede created KAFKA-666:
-----------------------------------
Summary: 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
Reporter: Neha Narkhede
Priority: Critical
Fix For: 0.8
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: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 20:59:22,611] TRACE Completed request with correlation id 0 and
client replica-fetcher-host_172.20.72.48-port_9092: FetchRequest:3301,
queueTime:1, localTime:3118, remoteTime:181, 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: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 is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
