You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Sachin Mittal <sj...@gmail.com> on 2017/03/02 12:13:52 UTC
Getting thread deadlock in streams 10.2.0 if a partition is
re-assigned to a different thread in same instance
Hi,
We are getting some deadlock state after re-balance and what we found that
it happens after re-balance the partition is assigned to a different thread
in same instance.
Looks like previous thread is not releasing the rocks db lock.
Here are the complete logs spanned across multiple files.
https://drive.google.com/open?id=0B-KsMy4P1bGxLTVVVWlZOGdQZTUzYm9aV3lfOFdubTJ2X2JR
I am just posting the gist here as how we understood this issue.
*===== TestKafkaAdvice.2017-03-01.89.log ========*
53352 INFO 2017-03-01 18:11:56,980 [StreamThread-3]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 96*
53353 INFO 2017-03-01 18:11:56,980 [StreamThread-4]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 96*
53354 INFO 2017-03-01 18:11:56,980 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 96*
53361 INFO 2017-03-01 *18:11:57,084* [StreamThread-1]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-1]
New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the end
of consumer rebalance.
53362 INFO 2017-03-01 18:11:57,084 [StreamThread-3]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-3]
New partitions [[advice-stream-7]]* assigned at the end of consumer
rebalance.
53363 DEBUG 2017-03-01 18:11:57,084 [StreamThread-3]:
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[StreamThread-3] closing suspended non-assigned task
53364 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - Setting
newly assigned partitions [advice-stream-8, advice-stream-2] fo r
group new-part-advice
53365 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
New partitions [[advice-stream-8, advice-strea**m-2]]* assigned at the end
of consumer rebalance.
54253 INFO 2017-03-01 18:13:19,146 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
Creating active task 0_2 with assigned partiti**ons [[advice-stream-2]]*
56789 INFO 2017-03-01 18:17:42,311 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 97*
56790 INFO 2017-03-01 18:17:42,311 [StreamThread-3]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 97*
56796 INFO 2017-03-01 *18:17:42,312* [StreamThread-3]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-3]
New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the end
of consumer rebalance.
56805 INFO 2017-03-01 18:17:42,312 [StreamThread-1]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-1]
New partitions [[advice-stream-8, advice-strea**m-4]]* assigned at the end
of consumer rebalance.
56823 INFO 2017-03-01 18:17:42,465 *[StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-1]
Creating active task 0_4 with assigned partiti**ons [[advice-stream-4]]*
56831 DEBUG 2017-03-01 18:17:42,531 *[StreamThread-1]*:
org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - Group
new-part-advice *fetching committed offsets for partitions: [advi**ce-stream-8,
advice-stream-4]*
57769 INFO 2017-03-01 *18:20:16,291* [StreamThread-4]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
Creating active task 0_8 with assigned partiti**ons [[advice-stream-8]]*
57935 INFO 2017-03-01 18:20:19,181 [StreamThread-4]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
Removing all active tasks [[0_2, 0_8]]*
*======== TestKafkaAdvice.2017-03-01.90.log ============*
742 INFO 2017-03-01 *18:22:42,697* [StreamThread-3]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 98*
743 INFO 2017-03-01 18:22:42,697 [StreamThread-4]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with *generation 98*
746 INFO 2017-03-01 18:22:42,697 [StreamThread-3]: org.apache.kafka.streams.
processor.internals.StreamThread - stream-thread *[StreamThread-3] New
partitions [[advice-stream-9, advice-stream**-4]]* assigned at the end of
consumer rebalance.
748 INFO 2017-03-01 18:22:42,712 [StreamThread-4]: org.apache.kafka.streams.
processor.internals.StreamThread - stream-thread *[StreamThread-4] New
partitions [[advice-stream-8, advice-stream**-2]]* assigned at the end of
consumer rebalance.
...............
4502 WARN 2017-03-01 *18:26:23,323* *[StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_4*. Will retry.
*************************************** Some time later.......*
4444 INFO 2017-03-01 18:25:44,071 [StreamThread-4]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
Removing all active tasks [[0_2, 0_8]]*
************************************
*Task 0_2 (from line # 54253) moved to a different instance's thread-3 and
Task 0_8 got re-assigned to Thread-4 (line # 4584 below)*
4474 INFO 2017-03-01 18:26:13,443 [StreamThread-1]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread [*StreamThread-1]
Creating active task 0_8 with assigned partitio**ns [[advice-stream-8]]*
4475 WARN 2017-03-01 18:26:14,445 *[StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_8*. Will retry.
4581 INFO 2017-03-01 *18:27:43,048* [StreamThread-4]:
org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
Successfully joined group new-part-advice with generation 99
4584 INFO 2017-03-01 18:27:43,048 [StreamThread-4]:
org.apache.kafka.streams.processor.internals.StreamThread -
stream-thread *[StreamThread-4]
New partitions [[advice-stream-8, advice-stream**-4]]* assigned at the end
of consumer rebalance.
************************************* Task Task 0_4 lock's as per line
#56823 above still seems to be with Thread-1 !!!*
4625 WARN 2017-03-01 *18:27:44,092* *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_4.* Will retry.
4646 WARN 2017-03-01 18:27:45,145 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
4955 WARN 2017-03-01 18:29:37,508 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
4982 WARN 2017-03-01 18:29:49,125 *[StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5073 WARN 2017-03-01 18:31:20,911 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5173 WARN 2017-03-01 18:34:46,714 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5199 WARN 2017-03-01 18:36:39,729 *[StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5248 WARN 2017-03-01 18:41:37,329 *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5279 WARN 2017-03-01 18:50:19,977 *[StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5397 WARN 2017-03-01 *19:19:13,900* *[StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_8*. Will retry.
5721 WARN 2017-03-01 *22:03:07,629 [StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_8*. Will retry.
5698 WARN 2017-03-01 *22:01:32,017* *[StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
5746 WARN 2017-03-01 *22:06:29,340* *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_4.* Will retry.
*======== TestKafkaAdvice.log ============*
148 WARN 2017-03-02 *01:41:35,831* *[StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_8.* Will retry.
735 WARN 2017-03-02 *08:58:31,234* *[StreamThread-1]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_8*. Will retry.
712 WARN 2017-03-02 *08:56:55,810 [StreamThread-3]*:
org.apache.kafka.streams.processor.internals.StreamThread - Could not
create task 0_4. Will retry.
760 WARN 2017-03-02 *09:01:52,945* *[StreamThread-4]*:
org.apache.kafka.streams.processor.internals.StreamThread - *Could not
create task 0_4*. Will retry.
*********************************** Finally all threads reach the
deadlock state where they cannot create task*
Please let us know, why we get such a deadlock state.
Thanks
Sachin
Re: Getting thread deadlock in streams 10.2.0 if a partition is
re-assigned to a different thread in same instance
Posted by Sachin Mittal <sj...@gmail.com>.
Hi,
It makes sense looks like task 0_4 took more than max poll timeout time.
However I have difficulty processing following lines:
DEBUG 2017-03-01 18:17:42,465 [StreamThread-1]:
org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
[StreamThread-1] creating new task 0_4
...
DEBUG 2017-03-01 18:17:42,590 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Handling
ListOffsetResponse response for new-part-advice-key-table-changelog-4.
Fetched offset 8591351, timestamp -1
DEBUG 2017-03-01 18:17:42,590 [StreamThread-1]:
org.apache.kafka.clients.consumer.KafkaConsumer - Seeking to beginning of
partition new-part-advice-key-table-changelog-4
DEBUG 2017-03-01 18:17:42,590 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Resetting offset for
partition new-part-advice-key-table-changelog-4 to earliest offset.
DEBUG 2017-03-01 18:17:42,591 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Handling
ListOffsetResponse response for new-part-advice-key-table-changelog-4.
Fetched offset 8408559, timestamp -1
DEBUG 2017-03-01 18:17:48,357 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Ignoring fetched
records for new-part-advice-key-table-changelog-4 at offset 8408559 since
the current position is 8411374
...
DEBUG 2017-03-01 18:24:18,585 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Ignoring fetched
records for new-part-advice-key-table-changelog-4 at offset 8590981 since
the current position is 8591351
DEBUG 2017-03-01 18:24:18,585 [StreamThread-1]:
org.apache.kafka.clients.consumer.internals.Fetcher - Sending fetch for
partitions [new-part-advice-key-table-changelog-4] to broker
192.168.73.199:9092 (id: 5 rack: null)
So when the new task is created it tries to replay the entire change log 4
partition from offset 8408559 to offset 8591351, and the whole process
takes about 7 minutes.
So why does it take so long to read some 180000 records? Is this some
rocksdb issue because it tries to recreate the entire state store.
Also why did it replay from the beginning? Shouldn't it have started from
somewhere in between, place where the previous thread to which this
partition was assigned, committed its offsets?
Thanks
Sachin
On Thu, Mar 2, 2017 at 9:05 PM, Damian Guy <da...@gmail.com> wrote:
> Hi Sachin,
>
> This is because another thread hasn't released the lock. It is generally
> caused because it is taking a long time to restore or process the incoming
> records. It might be helpful to take a Thread dump so we can see what each
> thread is doing.
>
> Thanks,
> Damian
>
> On Thu, 2 Mar 2017 at 12:14 Sachin Mittal <sj...@gmail.com> wrote:
>
> > Hi,
> > We are getting some deadlock state after re-balance and what we found
> that
> > it happens after re-balance the partition is assigned to a different
> thread
> > in same instance.
> >
> > Looks like previous thread is not releasing the rocks db lock.
> >
> > Here are the complete logs spanned across multiple files.
> >
> >
> > https://drive.google.com/open?id=0B-KsMy4P1bGxLTVVVWlZOGdQZTUzYm9a
> V3lfOFdubTJ2X2JR
> >
> > I am just posting the gist here as how we understood this issue.
> >
> >
> > *===== TestKafkaAdvice.2017-03-01.89.log ========*
> >
> > 53352 INFO 2017-03-01 18:11:56,980 [StreamThread-3]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 96*
> >
> > 53353 INFO 2017-03-01 18:11:56,980 [StreamThread-4]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 96*
> >
> > 53354 INFO 2017-03-01 18:11:56,980 [StreamThread-1]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 96*
> >
> >
> > 53361 INFO 2017-03-01 *18:11:57,084* [StreamThread-1]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-1]
> > New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the
> end
> > of consumer rebalance.
> >
> > 53362 INFO 2017-03-01 18:11:57,084 [StreamThread-3]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-3]
> > New partitions [[advice-stream-7]]* assigned at the end of consumer
> > rebalance.
> >
> > 53363 DEBUG 2017-03-01 18:11:57,084 [StreamThread-3]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread
> > [StreamThread-3] closing suspended non-assigned task
> >
> > 53364 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
> > org.apache.kafka.clients.consumer.internals.ConsumerCoordinator -
> Setting
> > newly assigned partitions [advice-stream-8, advice-stream-2] fo r
> > group new-part-advice
> >
> > 53365 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > New partitions [[advice-stream-8, advice-strea**m-2]]* assigned at the
> end
> > of consumer rebalance.
> >
> >
> >
> > 54253 INFO 2017-03-01 18:13:19,146 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > Creating active task 0_2 with assigned partiti**ons [[advice-stream-2]]*
> >
> >
> > 56789 INFO 2017-03-01 18:17:42,311 [StreamThread-1]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 97*
> >
> > 56790 INFO 2017-03-01 18:17:42,311 [StreamThread-3]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 97*
> >
> >
> > 56796 INFO 2017-03-01 *18:17:42,312* [StreamThread-3]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-3]
> > New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the
> end
> > of consumer rebalance.
> >
> > 56805 INFO 2017-03-01 18:17:42,312 [StreamThread-1]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-1]
> > New partitions [[advice-stream-8, advice-strea**m-4]]* assigned at the
> end
> > of consumer rebalance.
> >
> >
> >
> > 56823 INFO 2017-03-01 18:17:42,465 *[StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-1]
> > Creating active task 0_4 with assigned partiti**ons [[advice-stream-4]]*
> >
> > 56831 DEBUG 2017-03-01 18:17:42,531 *[StreamThread-1]*:
> > org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - Group
> > new-part-advice *fetching committed offsets for partitions:
> > [advi**ce-stream-8,
> > advice-stream-4]*
> >
> >
> >
> > 57769 INFO 2017-03-01 *18:20:16,291* [StreamThread-4]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > Creating active task 0_8 with assigned partiti**ons [[advice-stream-8]]*
> >
> >
> >
> >
> > 57935 INFO 2017-03-01 18:20:19,181 [StreamThread-4]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > Removing all active tasks [[0_2, 0_8]]*
> >
> >
> >
> > *======== TestKafkaAdvice.2017-03-01.90.log ============*
> >
> >
> > 742 INFO 2017-03-01 *18:22:42,697* [StreamThread-3]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 98*
> >
> > 743 INFO 2017-03-01 18:22:42,697 [StreamThread-4]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with *generation 98*
> >
> >
> > 746 INFO 2017-03-01 18:22:42,697 [StreamThread-3]:
> > org.apache.kafka.streams.
> > processor.internals.StreamThread - stream-thread *[StreamThread-3] New
> > partitions [[advice-stream-9, advice-stream**-4]]* assigned at the end of
> > consumer rebalance.
> >
> > 748 INFO 2017-03-01 18:22:42,712 [StreamThread-4]:
> > org.apache.kafka.streams.
> > processor.internals.StreamThread - stream-thread *[StreamThread-4] New
> > partitions [[advice-stream-8, advice-stream**-2]]* assigned at the end of
> > consumer rebalance.
> >
> > ...............
> >
> > 4502 WARN 2017-03-01 *18:26:23,323* *[StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_4*. Will retry.
> >
> >
> > *************************************** Some time later.......*
> >
> >
> > 4444 INFO 2017-03-01 18:25:44,071 [StreamThread-4]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > Removing all active tasks [[0_2, 0_8]]*
> >
> >
> > ************************************
> > *Task 0_2 (from line # 54253) moved to a different instance's thread-3
> and
> > Task 0_8 got re-assigned to Thread-4 (line # 4584 below)*
> >
> >
> > 4474 INFO 2017-03-01 18:26:13,443 [StreamThread-1]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread [*StreamThread-1]
> > Creating active task 0_8 with assigned partitio**ns [[advice-stream-8]]*
> >
> > 4475 WARN 2017-03-01 18:26:14,445 *[StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_8*. Will retry.
> >
> >
> >
> >
> > 4581 INFO 2017-03-01 *18:27:43,048* [StreamThread-4]:
> > org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> > Successfully joined group new-part-advice with generation 99
> >
> >
> > 4584 INFO 2017-03-01 18:27:43,048 [StreamThread-4]:
> > org.apache.kafka.streams.processor.internals.StreamThread -
> > stream-thread *[StreamThread-4]
> > New partitions [[advice-stream-8, advice-stream**-4]]* assigned at the
> end
> > of consumer rebalance.
> >
> >
> > ************************************* Task Task 0_4 lock's as per line
> > #56823 above still seems to be with Thread-1 !!!*
> >
> >
> > 4625 WARN 2017-03-01 *18:27:44,092* *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_4.* Will retry.
> >
> > 4646 WARN 2017-03-01 18:27:45,145 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 4955 WARN 2017-03-01 18:29:37,508 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 4982 WARN 2017-03-01 18:29:49,125 *[StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5073 WARN 2017-03-01 18:31:20,911 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5173 WARN 2017-03-01 18:34:46,714 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5199 WARN 2017-03-01 18:36:39,729 *[StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5248 WARN 2017-03-01 18:41:37,329 *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5279 WARN 2017-03-01 18:50:19,977 *[StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> >
> > 5397 WARN 2017-03-01 *19:19:13,900* *[StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_8*. Will retry.
> >
> > 5721 WARN 2017-03-01 *22:03:07,629 [StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_8*. Will retry.
> >
> >
> > 5698 WARN 2017-03-01 *22:01:32,017* *[StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 5746 WARN 2017-03-01 *22:06:29,340* *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_4.* Will retry.
> >
> >
> > *======== TestKafkaAdvice.log ============*
> >
> >
> > 148 WARN 2017-03-02 *01:41:35,831* *[StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_8.* Will retry.
> >
> > 735 WARN 2017-03-02 *08:58:31,234* *[StreamThread-1]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_8*. Will retry.
> >
> >
> > 712 WARN 2017-03-02 *08:56:55,810 [StreamThread-3]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - Could not
> > create task 0_4. Will retry.
> >
> > 760 WARN 2017-03-02 *09:01:52,945* *[StreamThread-4]*:
> > org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> > create task 0_4*. Will retry.
> >
> >
> > *********************************** Finally all threads reach the
> > deadlock state where they cannot create task*
> >
> >
> > Please let us know, why we get such a deadlock state.
> >
> >
> > Thanks
> >
> > Sachin
> >
>
Re: Getting thread deadlock in streams 10.2.0 if a partition is
re-assigned to a different thread in same instance
Posted by Damian Guy <da...@gmail.com>.
Hi Sachin,
This is because another thread hasn't released the lock. It is generally
caused because it is taking a long time to restore or process the incoming
records. It might be helpful to take a Thread dump so we can see what each
thread is doing.
Thanks,
Damian
On Thu, 2 Mar 2017 at 12:14 Sachin Mittal <sj...@gmail.com> wrote:
> Hi,
> We are getting some deadlock state after re-balance and what we found that
> it happens after re-balance the partition is assigned to a different thread
> in same instance.
>
> Looks like previous thread is not releasing the rocks db lock.
>
> Here are the complete logs spanned across multiple files.
>
>
> https://drive.google.com/open?id=0B-KsMy4P1bGxLTVVVWlZOGdQZTUzYm9aV3lfOFdubTJ2X2JR
>
> I am just posting the gist here as how we understood this issue.
>
>
> *===== TestKafkaAdvice.2017-03-01.89.log ========*
>
> 53352 INFO 2017-03-01 18:11:56,980 [StreamThread-3]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 96*
>
> 53353 INFO 2017-03-01 18:11:56,980 [StreamThread-4]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 96*
>
> 53354 INFO 2017-03-01 18:11:56,980 [StreamThread-1]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 96*
>
>
> 53361 INFO 2017-03-01 *18:11:57,084* [StreamThread-1]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-1]
> New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the end
> of consumer rebalance.
>
> 53362 INFO 2017-03-01 18:11:57,084 [StreamThread-3]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-3]
> New partitions [[advice-stream-7]]* assigned at the end of consumer
> rebalance.
>
> 53363 DEBUG 2017-03-01 18:11:57,084 [StreamThread-3]:
> org.apache.kafka.streams.processor.internals.StreamThread - stream-thread
> [StreamThread-3] closing suspended non-assigned task
>
> 53364 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
> org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - Setting
> newly assigned partitions [advice-stream-8, advice-stream-2] fo r
> group new-part-advice
>
> 53365 INFO 2017-03-01 18:11:57,084 [StreamThread-4]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> New partitions [[advice-stream-8, advice-strea**m-2]]* assigned at the end
> of consumer rebalance.
>
>
>
> 54253 INFO 2017-03-01 18:13:19,146 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> Creating active task 0_2 with assigned partiti**ons [[advice-stream-2]]*
>
>
> 56789 INFO 2017-03-01 18:17:42,311 [StreamThread-1]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 97*
>
> 56790 INFO 2017-03-01 18:17:42,311 [StreamThread-3]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 97*
>
>
> 56796 INFO 2017-03-01 *18:17:42,312* [StreamThread-3]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-3]
> New partitions [[advice-stream-9, advice-strea**m-6]]* assigned at the end
> of consumer rebalance.
>
> 56805 INFO 2017-03-01 18:17:42,312 [StreamThread-1]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-1]
> New partitions [[advice-stream-8, advice-strea**m-4]]* assigned at the end
> of consumer rebalance.
>
>
>
> 56823 INFO 2017-03-01 18:17:42,465 *[StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-1]
> Creating active task 0_4 with assigned partiti**ons [[advice-stream-4]]*
>
> 56831 DEBUG 2017-03-01 18:17:42,531 *[StreamThread-1]*:
> org.apache.kafka.clients.consumer.internals.ConsumerCoordinator - Group
> new-part-advice *fetching committed offsets for partitions:
> [advi**ce-stream-8,
> advice-stream-4]*
>
>
>
> 57769 INFO 2017-03-01 *18:20:16,291* [StreamThread-4]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> Creating active task 0_8 with assigned partiti**ons [[advice-stream-8]]*
>
>
>
>
> 57935 INFO 2017-03-01 18:20:19,181 [StreamThread-4]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> Removing all active tasks [[0_2, 0_8]]*
>
>
>
> *======== TestKafkaAdvice.2017-03-01.90.log ============*
>
>
> 742 INFO 2017-03-01 *18:22:42,697* [StreamThread-3]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 98*
>
> 743 INFO 2017-03-01 18:22:42,697 [StreamThread-4]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with *generation 98*
>
>
> 746 INFO 2017-03-01 18:22:42,697 [StreamThread-3]:
> org.apache.kafka.streams.
> processor.internals.StreamThread - stream-thread *[StreamThread-3] New
> partitions [[advice-stream-9, advice-stream**-4]]* assigned at the end of
> consumer rebalance.
>
> 748 INFO 2017-03-01 18:22:42,712 [StreamThread-4]:
> org.apache.kafka.streams.
> processor.internals.StreamThread - stream-thread *[StreamThread-4] New
> partitions [[advice-stream-8, advice-stream**-2]]* assigned at the end of
> consumer rebalance.
>
> ...............
>
> 4502 WARN 2017-03-01 *18:26:23,323* *[StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_4*. Will retry.
>
>
> *************************************** Some time later.......*
>
>
> 4444 INFO 2017-03-01 18:25:44,071 [StreamThread-4]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> Removing all active tasks [[0_2, 0_8]]*
>
>
> ************************************
> *Task 0_2 (from line # 54253) moved to a different instance's thread-3 and
> Task 0_8 got re-assigned to Thread-4 (line # 4584 below)*
>
>
> 4474 INFO 2017-03-01 18:26:13,443 [StreamThread-1]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread [*StreamThread-1]
> Creating active task 0_8 with assigned partitio**ns [[advice-stream-8]]*
>
> 4475 WARN 2017-03-01 18:26:14,445 *[StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_8*. Will retry.
>
>
>
>
> 4581 INFO 2017-03-01 *18:27:43,048* [StreamThread-4]:
> org.apache.kafka.clients.consumer.internals.AbstractCoordinator -
> Successfully joined group new-part-advice with generation 99
>
>
> 4584 INFO 2017-03-01 18:27:43,048 [StreamThread-4]:
> org.apache.kafka.streams.processor.internals.StreamThread -
> stream-thread *[StreamThread-4]
> New partitions [[advice-stream-8, advice-stream**-4]]* assigned at the end
> of consumer rebalance.
>
>
> ************************************* Task Task 0_4 lock's as per line
> #56823 above still seems to be with Thread-1 !!!*
>
>
> 4625 WARN 2017-03-01 *18:27:44,092* *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_4.* Will retry.
>
> 4646 WARN 2017-03-01 18:27:45,145 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 4955 WARN 2017-03-01 18:29:37,508 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 4982 WARN 2017-03-01 18:29:49,125 *[StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5073 WARN 2017-03-01 18:31:20,911 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5173 WARN 2017-03-01 18:34:46,714 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5199 WARN 2017-03-01 18:36:39,729 *[StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5248 WARN 2017-03-01 18:41:37,329 *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5279 WARN 2017-03-01 18:50:19,977 *[StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
>
> 5397 WARN 2017-03-01 *19:19:13,900* *[StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_8*. Will retry.
>
> 5721 WARN 2017-03-01 *22:03:07,629 [StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_8*. Will retry.
>
>
> 5698 WARN 2017-03-01 *22:01:32,017* *[StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 5746 WARN 2017-03-01 *22:06:29,340* *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_4.* Will retry.
>
>
> *======== TestKafkaAdvice.log ============*
>
>
> 148 WARN 2017-03-02 *01:41:35,831* *[StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_8.* Will retry.
>
> 735 WARN 2017-03-02 *08:58:31,234* *[StreamThread-1]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_8*. Will retry.
>
>
> 712 WARN 2017-03-02 *08:56:55,810 [StreamThread-3]*:
> org.apache.kafka.streams.processor.internals.StreamThread - Could not
> create task 0_4. Will retry.
>
> 760 WARN 2017-03-02 *09:01:52,945* *[StreamThread-4]*:
> org.apache.kafka.streams.processor.internals.StreamThread - *Could not
> create task 0_4*. Will retry.
>
>
> *********************************** Finally all threads reach the
> deadlock state where they cannot create task*
>
>
> Please let us know, why we get such a deadlock state.
>
>
> Thanks
>
> Sachin
>