kafka restart then sarama consumer has very high cpu

[junweiyang]

Versions

Please specify real version numbers or git SHAs, not just "Latest" since that changes fairly regularly.
Sarama Version: Version 1.11.0 (2016-12-20)
Kafka Version: 0.8.22
Go Version: 1.7.3

Configuration

What configuration values are you using for Sarama and Kafka?
default consumer configuration

Logs

15:38:05 clock_gettime(CLOCK_MONOTONIC, {17385743, 235245143}) = 0
15:38:05 futex(0xa7c358, FUTEX_WAIT, 0, {4, 974182315}) = -1 ETIMEDOUT (Connection timed out)
15:38:10 clock_gettime(CLOCK_MONOTONIC, {17385748, 213971600}) = 0
15:38:10 futex(0xa7d510, FUTEX_WAIT, 0, NULL) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 183737890}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 184469516}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 184600796}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 184784901}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 185386391}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 185642099}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 185759319}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 186226747}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 186733242}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 187221431}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 187472697}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 187833118}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 188202916}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 188411127}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 188785893}) = 0
15:38:10 clock_gettime(CLOCK_REALTIME, {1489995490, 189176483}) = 0

ps aux |grep xxx
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
19515 ecuser 20 0 271m 4760 1796 R 23.6 0.3 124:33.53 ecwebrest

Problem Description

when kafka restsart Sarama client has very high cpu , it's seems that sarama don't deal reconnect kafka!

normal strace log

17:49:48 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:48 epoll_wait(5, {}, 128, 0) = 0
17:49:48 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:49 epoll_wait(5, {}, 128, 0) = 0
17:49:49 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:49 epoll_wait(5, {}, 128, 0) = 0
17:49:49 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:49 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:49 epoll_wait(5, {}, 128, 0) = 0
17:49:49 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:50 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:50 epoll_wait(5, {}, 128, 0) = 0
17:49:50 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:50 epoll_wait(5, {}, 128, 0) = 0
17:49:50 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:50 epoll_wait(5, {}, 128, 0) = 0
17:49:50 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:51 epoll_wait(5, {}, 128, 0) = 0
17:49:51 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:51 epoll_wait(5, {}, 128, 0) = 0
17:49:51 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:51 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:51 epoll_wait(5, {}, 128, 0) = 0
17:49:51 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:52 epoll_wait(5, {}, 128, 0) = 0
17:49:52 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:52 epoll_wait(5, {}, 128, 0) = 0
17:49:52 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:52 epoll_wait(5, {}, 128, 0) = 0
17:49:52 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:52 epoll_wait(5, {}, 128, 0) = 0
17:49:52 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:53 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:53 epoll_wait(5, {}, 128, 0) = 0
17:49:53 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:53 epoll_wait(5, {}, 128, 0) = 0
17:49:53 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:53 epoll_wait(5, {}, 128, 0) = 0
17:49:53 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:53 epoll_wait(5, {}, 128, 0) = 0
17:49:53 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:54 epoll_wait(5, {}, 128, 0) = 0
17:49:54 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:54 epoll_wait(5, {{EPOLLOUT, {u32=2524166296, u64=140263271151768}}}, 128, 0) = 1
17:49:54 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:54 futex(0xa79510, FUTEX_WAIT, 0, NULL) = 0
17:49:54 epoll_wait(5, {}, 128, 0) = 0

i think sarama is dead locked

[eapache]

You can set sarama.Logger to a log.Logger instance to capture debug output. Please include it in your issue description.

[junweiyang]

@eapache sorry my fault! i forgot set sarama.Logger...

[gdutliuyun827]

I encountered the same problem; the log is below,but no more information
Sarama Version: 92a286e
Kafka Version: kafka_2.11-0.10.1.0
Go Version: 1.8

[kafka] 11:03:55.058752 client.go:107: Initializing new client
[kafka] 11:03:55.058973 client.go:585: client/metadata fetching metadata for all topics from broker 10.1.169.52:9092
[kafka] 11:03:55.059187 broker.go:91: Connected to broker at 10.1.169.52:9092 (unregistered)
[kafka] 11:03:55.060728 client.go:384: client/brokers registered new broker #52 at 10.1.169.52:9092
[kafka] 11:03:55.060752 client.go:384: client/brokers registered new broker #51 at 10.1.169.51:9092
[kafka] 11:03:55.060785 client.go:151: Successfully initialized new client
[kafka] 11:03:55.305342 broker.go:89: Connected to broker at 10.1.169.52:9092 (registered as #52)
[kafka] 11:03:55.307581 consumer.go:611: consumer/broker/52 added subscription to topicTest/0
[kafka] 11:03:55.307825 broker.go:89: Connected to broker at 10.1.169.51:9092 (registered as #51)
[kafka] 11:03:55.308815 consumer.go:611: consumer/broker/51 added subscription to topicTest/1
[kafka] 11:03:55.341094 consumer.go:611: consumer/broker/51 added subscription to topicTest/3
[kafka] 11:03:55.346179 consumer.go:611: consumer/broker/52 added subscription to topicTest/2
[kafka] 11:03:55.457479 consumer.go:637: consumer/broker/51 abandoned subscription to topicTest/1 because consuming was taking too long
[kafka] 11:03:55.586387 consumer.go:637: consumer/broker/51 abandoned subscription to topicTest/3 because consuming was taking too long
[kafka] 11:03:55.688368 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/0 because consuming was taking too long
[kafka] 11:03:55.794500 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/2 because consuming was taking too long
[kafka] 11:04:30.336248 consumer.go:611: consumer/broker/52 added subscription to topicTest/0
[kafka] 11:04:30.390888 consumer.go:611: consumer/broker/51 added subscription to topicTest/3
[kafka] 11:04:30.390948 consumer.go:594: consumer/broker/51 disconnecting due to error processing FetchRequest: EOF
[kafka] 11:04:30.390983 broker.go:127: Closed connection to broker 10.1.169.51:9092
[kafka] 11:04:30.391252 client.go:174: Closing Client
[kafka] 11:04:30.391325 broker.go:127: Closed connection to broker 10.1.169.52:9092
[kafka] 11:04:30.391344 broker.go:127: Closed connection to broker 10.1.169.52:9092
[kafka] 11:04:30.491216 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/0 because consuming was taking too long
[kafka] 11:04:30.491383 client.go:107: Initializing new client
[kafka] 11:04:30.491499 client.go:585: client/metadata fetching metadata for all topics from broker 10.1.169.52:9092
[kafka] 11:04:30.491636 broker.go:91: Connected to broker at 10.1.169.52:9092 (unregistered)
[kafka] 11:04:30.493967 client.go:384: client/brokers registered new broker #52 at 10.1.169.52:9092
[kafka] 11:04:30.494003 client.go:151: Successfully initialized new client
[kafka] 11:04:30.738799 broker.go:89: Connected to broker at 10.1.169.52:9092 (registered as #52)
[kafka] 11:04:30.741682 consumer.go:611: consumer/broker/52 added subscription to topicTest/0
[kafka] 11:04:30.751709 consumer.go:611: consumer/broker/52 added subscription to topicTest/1
[kafka] 11:04:30.761736 consumer.go:611: consumer/broker/52 added subscription to topicTest/2
[kafka] 11:04:30.773583 consumer.go:611: consumer/broker/52 added subscription to topicTest/3
[kafka] 11:04:49.333807 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/3 because consuming was taking too long
[kafka] 11:04:49.524244 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/1 because consuming was taking too long
[kafka] 11:04:49.524296 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/2 because consuming was taking too long
[kafka] 11:04:49.626050 consumer.go:637: consumer/broker/52 abandoned subscription to topicTest/0 because consuming was taking too long
[kafka] 11:05:31.256883 client.go:107: Initializing new client
[kafka] 11:05:31.256941 client.go:585: client/metadata fetching metadata for all topics from broker 10.1.169.52:9092
[kafka] 11:05:31.257087 broker.go:91: Connected to broker at 10.1.169.52:9092 (unregistered)
[kafka] 11:05:31.258333 client.go:384: client/brokers registered new broker #52 at 10.1.169.52:9092
[kafka] 11:05:31.258362 client.go:384: client/brokers registered new broker #51 at 10.1.169.51:9092
[kafka] 11:05:31.258388 client.go:151: Successfully initialized new client
[kafka] 11:05:31.258578 broker.go:89: Connected to broker at 10.1.169.52:9092 (registered as #52)
[kafka] 11:05:31.264060 client.go:174: Closing Client
[kafka] 11:05:31.264176 broker.go:127: Closed connection to broker 10.1.169.52:9092
[kafka] 11:05:31.264176 broker.go:127: Closed connection to broker 10.1.169.52:9092
[kafka] 11:06:34.260270 client.go:107: Initializing new client
[kafka] 11:06:34.260332 client.go:585: client/metadata fetching metadata for all topics from broker 10.1.169.52:9092
[kafka] 11:06:34.260494 broker.go:91: Connected to broker at 10.1.169.52:9092 (unregistered)
[kafka] 11:06:34.261736 client.go:384: client/brokers registered new broker #52 at 10.1.169.52:9092
[kafka] 11:06:34.261761 client.go:384: client/brokers registered new broker #51 at 10.1.169.51:9092
[kafka] 11:06:34.261790 client.go:151: Successfully initialized new client
[kafka] 11:06:34.261916 broker.go:89: Connected to broker at 10.1.169.52:9092 (registered as #52)
[kafka] 11:06:34.266984 client.go:174: Closing Client
[kafka] 11:06:34.267140 broker.go:127: Closed connection to broker 10.1.169.52:9092

[eapache]

@gdutliuyun827 that version of sarama is older, and the bug you are seeing is probably #693.

[gdutliuyun827]

upgrade the lib No longer appear, thanks!

[wvanbergen]

Awesome ✨