Joe created KAFKA-13475:
---------------------------
Summary: max-compaction-delay-secs reported at one clean "behind"
current state
Key: KAFKA-13475
URL: https://issues.apache.org/jira/browse/KAFKA-13475
Project: Kafka
Issue Type: Bug
Components: log cleaner
Affects Versions: 3.0.0
Reporter: Joe
We have a compacted topic with a very slow rate of incoming messages, along
with other much faster topics.
On the slow topic, {{max.compaction.lag.ms}} is set to 1209600000 (14 days).
The first message was produced on 2021-11-05, and the second message, with the
same key, was produced 2021-11-24. The log cleaner immediately started and
cleaned the partition, but the {{max-compaction-delay-secs}} metric continued
reporting cleaning was 5 days delayed, until the *next* partition was cleaned:
{noformat}
[2021-11-24 12:35:33,767] INFO [kafka-log-cleaner-thread-2]: Cleanable
partitions: 1, Delayed partitions: 1, max delay: 1150 (kafka.log.LogCleaner)
[2021-11-24 12:43:49,135] INFO Cleaner 2: Beginning cleaning of log slow-0.
(kafka.log.LogCleaner)
[2021-11-24 12:43:49,135] INFO Cleaner 2: Building offset map for slow-0...
(kafka.log.LogCleaner)
[2021-11-24 12:43:49,457] INFO Cleaner 2: Building offset map for log slow-0
for 1 segments in offset range [0, 1). (kafka.log.LogCleaner)
[2021-11-24 12:43:49,457] INFO Cleaner 2: Offset map for log slow-0 complete.
(kafka.log.LogCleaner)
[2021-11-24 12:43:49,458] INFO Cleaner 2: Cleaning log slow-0 (cleaning prior
to Fri Nov 05 14:15:49 CET 2021, discarding tombstones prior to Thu Jan 01
01:00:00 CET 1970)... (kafka.log.LogCleaner)
[2021-11-24 12:43:49,459] INFO Cleaner 2: Cleaning LogSegment(baseOffset=0,
size=205, lastModifiedTime=1636118149816,
largestRecordTimestamp=Some(1636118148817)) in log slow-0 into 0 with deletion
horizon 0, retaining deletes. (kafka.log.LogCleaner)
[2021-11-24 12:43:49,466] INFO Cleaner 2: Swapping in cleaned segment
LogSegment(baseOffset=0, size=205, lastModifiedTime=1636118149816,
largestRecordTimestamp=Some(1636118148817)) for segment(s)
List(LogSegment(baseOffset=0, size=205, lastModifiedTime=1636118149816,
largestRecordTimestamp=Some(1636118148817))) in log Log(dir=/data/kafka/slow-0,
topicId=UZ8ZjcljSvefr-YOKbkjGw, topic=dataset, partition=0, highWatermark=2,
lastStableOffset=2, logStartOffset=0, logEndOffset=2) (kafka.log.LogCleaner)
[2021-11-24 12:43:49,467] INFO [kafka-log-cleaner-thread-2]:
Log cleaner thread 2 cleaned log slow-0 (dirty section = [0, 1])
0.0 MB of log processed in 0.3 seconds (0.0 MB/sec).
Indexed 0.0 MB in 0.3 seconds (0.0 Mb/sec, 97.3% of total time)
Buffer utilization: 0.0%
Cleaned 0.0 MB in 0.0 seconds (0.0 Mb/sec, 2.7% of total time)
Start size: 0.0 MB (1 messages)
End size: 0.0 MB (1 messages)
0.0% size reduction (0.0% fewer messages)
(kafka.log.LogCleaner)
[2021-11-24 12:43:49,467] INFO [kafka-log-cleaner-thread-2]: Cleanable
partitions: 1, Delayed partitions: 1, max delay: 426480297
(kafka.log.LogCleaner)
[2021-11-24 14:06:08,164] INFO Cleaner 2: Beginning cleaning of log fast-45.
(kafka.log.LogCleaner)
...
[2021-11-24 14:06:26,576] INFO [kafka-log-cleaner-thread-2]:
Log cleaner thread 2 cleaned log fast-45 (dirty section = [437517047,
437564906])
1,518.5 MB of log processed in 18.4 seconds (82.5 MB/sec).
Indexed 21.3 MB in 0.4 seconds (49.8 Mb/sec, 2.3% of total time)
Buffer utilization: 0.1%
Cleaned 1,518.5 MB in 18.0 seconds (84.4 Mb/sec, 97.7% of total time)
Start size: 1,518.5 MB (12,054,661 messages)
End size: 1,500.7 MB (12,008,059 messages)
1.2% size reduction (0.4% fewer messages)
(kafka.log.LogCleaner)
[2021-11-24 14:06:26,576] INFO [kafka-log-cleaner-thread-2]: Cleanable
partitions: 1, Delayed partitions: 1, max delay: 3051 (kafka.log.LogCleaner)
{noformat}
Between 12:43 and 14:06, {{max-compaction-delay-secs}} was still reported as
426480. Unfortunately, this was enough to confuse our alerts (and developers).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
