[jira] [Created] (KAFKA-13475) max-compaction-delay-secs reported at one clean "behind" current state

["Joe (Jira)" <ji...@apache.org>]

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)