[KAFKA-13054] Unexpected Polling Behavior

• Type: Improvement
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.8.0
• Component/s: core
• Assignee: Unassigned
• Reporter: Gary Russell
• Created: 08/Jul/21 21:29
• Updated: 08/Jul/21 21:55

Description

Given a topic with 10 partitions and 9000 records (evenly distributed) and

max.poll.records: 2000
fetch.max.bytes = 52428800
fetch.max.wait.ms = 10000
fetch.min.bytes = 10240000

We see odd results

log.info("" + recs.count() + "\n"
	+ recs.partitions().stream()
		.map(part -> "" + part.partition() 
			+ "(" + recs.records(part).size() + ")")
		.collect(Collectors.toList()));

Result:

2021-07-08 15:04:11.131  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 2000
[1(201), 0(201), 5(201), 4(201), 3(201), 2(201), 9(201), 8(201), 7(201), 6(191)]
2021-07-08 15:04:11.137  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 10
[6(10)]
2021-07-08 15:04:21.170  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 1809
[1(201), 0(201), 5(201), 4(201), 3(201), 2(201), 9(201), 8(201), 7(201)]
2021-07-08 15:04:21.214  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 2000
[1(201), 0(201), 5(201), 4(201), 3(201), 2(201), 9(201), 8(201), 7(201), 6(191)]
2021-07-08 15:04:21.215  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 10
[6(10)]
2021-07-08 15:04:31.248  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 1809
[1(201), 0(201), 5(201), 4(201), 3(201), 2(201), 9(201), 8(201), 7(201)]
2021-07-08 15:04:41.267  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 1083
[1(27), 0(87), 5(189), 4(93), 3(114), 2(129), 9(108), 8(93), 7(42), 6(201)]
2021-07-08 15:04:51.276  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 201
[6(201)]
2021-07-08 15:05:01.279  INFO 45792 --- [o68201599-0-C-1] com.example.demo.So68201599Application   : 78
[6(78)]

I can understand the second poll returning immediately (presumably over-fetch from the previous poll) but why does the third poll take 10 seconds (fetch.max.wait)? The fourth and fifth polls are like the first and second and return almost immediately, but the sixth once again takes 10 seconds and returns a partial result.

Is there a document that explains the fetch mechanism that might explain this behavior?