Fascinating.
We are seeing no errors or warning in the logs after restart. It appears on
this broker that the compaction thread is working:
[2016-06-22 10:33:49,179] INFO Rolled new log segment for
'__consumer_offsets-28' in 1 ms. (kafka.log.Log)
[2016-06-22 10:34:00,968] INFO Deleting segment 0 from log
__consumer_offsets-28. (kafka.log.Log)
[2016-06-22 10:34:00,970] INFO Deleting index
/kafka/data/__consumer_offsets-28/00000000000000000000.index.deleted
(kafka.log.OffsetIndex)
[2016-06-22 10:34:00,992] INFO Deleting segment 2148144095 from log
__consumer_offsets-28. (kafka.log.Log)
[2016-06-22 10:34:00,994] INFO Deleting index
/kafka/data/__consumer_offsets-28/00000000002148144095.index.deleted
(kafka.log.OffsetIndex)
[2016-06-22 10:34:01,002] INFO Deleting segment 3189277822 from log
__consumer_offsets-28. (kafka.log.Log)
[2016-06-22 10:34:01,004] INFO Deleting index
/kafka/data/__consumer_offsets-28/00000000003189277822.index.deleted
(kafka.log.OffsetIndex)
[2016-06-22 10:34:02,019] INFO Deleting segment 3190205744 from log
__consumer_offsets-28. (kafka.log.Log)
[2016-06-22 10:34:02,039] INFO Deleting index
/kafka/data/__consumer_offsets-28/00000000003190205744.index.deleted
(kafka.log.OffsetIndex)
We see the “kafka-log-cleaner-thread” in the JMX. It seems to run about every
50 seconds. From the log-cleaner.log file, we see plenty of this output
regarding the partition that’s hogging the FDs:
[2016-06-22 10:44:31,845] INFO Cleaner 0: Beginning cleaning of log
__consumer_offsets-28. (kafka.log.LogCleaner)
[2016-06-22 10:44:31,846] INFO Cleaner 0: Building offset map for
__consumer_offsets-28... (kafka.log.LogCleaner)
[2016-06-22 10:44:31,878] INFO Cleaner 0: Building offset map for log
__consumer_offsets-28 for 1 segments in offset range [3204124461, 3205052375).
(kafka.log.LogCleaner)
[2016-06-22 10:44:32,870] INFO Cleaner 0: Offset map for log
__consumer_offsets-28 complete. (kafka.log.LogCleaner)
[2016-06-22 10:44:32,871] INFO Cleaner 0: Cleaning log __consumer_offsets-28
(discarding tombstones prior to Tue Jun 21 10:43:19 PDT 2016)...
(kafka.log.LogCleaner)
[2016-06-22 10:44:32,871] INFO Cleaner 0: Cleaning segment 0 in log
__consumer_offsets-28 (last modified Tue Jun 21 22:39:18 PDT 2016) into 0,
retaining deletes. (kafka.log.LogCleaner)
[2016-06-22 10:44:32,888] INFO Cleaner 0: Swapping in cleaned segment 0 for
segment(s) 0 in log __consumer_offsets-28. (kafka.log.LogCleaner)
[2016-06-22 10:44:32,889] INFO Cleaner 0: Cleaning segment 2148144095 in log
__consumer_offsets-28 (last modified Wed Jun 22 10:42:31 PDT 2016) into
2148144095, retaining deletes. (kafka.log.LogCleaner)
[2016-06-22 10:44:32,889] INFO Cleaner 0: Cleaning segment 3203196540 in log
__consumer_offsets-28 (last modified Wed Jun 22 10:43:19 PDT 2016) into
2148144095, retaining deletes. (kafka.log.LogCleaner)
[2016-06-22 10:44:32,905] INFO Cleaner 0: Swapping in cleaned segment
2148144095 for segment(s) 2148144095,3203196540 in log __consumer_offsets-28.
(kafka.log.LogCleaner)
[2016-06-22 10:44:32,905] INFO Cleaner 0: Cleaning segment 3204124461 in log
__consumer_offsets-28 (last modified Wed Jun 22 10:44:21 PDT 2016) into
3204124461, retaining deletes. (kafka.log.LogCleaner)
[2016-06-22 10:44:33,834] INFO Cleaner 0: Swapping in cleaned segment
3204124461 for segment(s) 3204124461 in log __consumer_offsets-28.
(kafka.log.LogCleaner)
[2016-06-22 10:44:33,836] INFO [kafka-log-cleaner-thread-0],
Log cleaner thread 0 cleaned log __consumer_offsets-28 (dirty section =
[3204124461, 3205052375])
100.0 MB of log processed in 2.0 seconds (50.3 MB/sec).
Indexed 100.0 MB in 1.0 seconds (97.6 Mb/sec, 51.5% of total time)
Buffer utilization: 0.0%
Cleaned 100.0 MB in 1.0 seconds (103.6 Mb/sec, 48.5% of total time)
Start size: 100.0 MB (928,011 messages)
End size: 0.0 MB (97 messages)
100.0% size reduction (100.0% fewer messages)
(kafka.log.LogCleaner)
But no actual delete messages like a properly-working broker is showing of a
different partition.
Lawrence Weikum
On 6/22/16, 11:28 AM, "Tom Crayford" <tcrayf...@heroku.com> wrote:
kafka-log-cleaner-thread-0
