kafka-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Tomislav Rajakovic (JIRA)" <j...@apache.org>
Subject [jira] [Created] (KAFKA-8764) LogCleanerManager endless loop while compacting/cleaning segments
Date Wed, 07 Aug 2019 13:17:00 GMT
Tomislav Rajakovic created KAFKA-8764:
-----------------------------------------

             Summary: LogCleanerManager endless loop while compacting/cleaning segments
                 Key: KAFKA-8764
                 URL: https://issues.apache.org/jira/browse/KAFKA-8764
             Project: Kafka
          Issue Type: Bug
          Components: log cleaner
    Affects Versions: 2.2.1
         Environment: docker base image: openjdk:8-jre-alpine base image, kafka from http://ftp.carnet.hr/misc/apache/kafka/2.2.1/kafka_2.12-2.2.1.tgz
            Reporter: Tomislav Rajakovic
         Attachments: log-cleaner-bug-reproduction.zip

{{LogCleanerManager stuck in endless loop while clearing segments for one partition resulting
with many log outputs and heavy disk read/writes/IOPS.}}

 

Issue appeared on follower brokers, and it happens on every (new) broker if partition assignment
is changed.

 

Original issue setup:
 * kafka_2.12-2.2.1 deployed as statefulset on kubernetes, 5 brokers
 * log directory is (AWS) EBS mounted PV, gp2 (ssd) kind of 750GiB
 * 5 zookeepers
 * topic created with config:
 ** name = "backup_br_domain_squad"
partitions = 36
replication_factor = 3

config = {
 "cleanup.policy" = "compact"
 "min.compaction.lag.ms" = "86400000"
 "min.cleanable.dirty.ratio" = "0.3"
}

 

 

Log excerpt:

{{[2019-08-07 12:10:53,895] INFO [Log partition=backup_br_domain_squad-14, dir=/var/lib/kafka/data/topics]
Deleting segment 0 (kafka.log.Log)}}
{{[2019-08-07 12:10:53,895] INFO Deleted log /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.log.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:53,896] INFO Deleted offset index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.index.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:53,896] INFO Deleted time index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.timeindex.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:53,964] INFO [Log partition=backup_br_domain_squad-14, dir=/var/lib/kafka/data/topics]
Deleting segment 0 (kafka.log.Log)}}
{{[2019-08-07 12:10:53,964] INFO Deleted log /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.log.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:53,964] INFO Deleted offset index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.index.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:53,964] INFO Deleted time index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.timeindex.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,031] INFO [Log partition=backup_br_domain_squad-14, dir=/var/lib/kafka/data/topics]
Deleting segment 0 (kafka.log.Log)}}
{{[2019-08-07 12:10:54,032] INFO Deleted log /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.log.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,032] INFO Deleted offset index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.index.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,032] INFO Deleted time index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.timeindex.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,101] INFO [Log partition=backup_br_domain_squad-14, dir=/var/lib/kafka/data/topics]
Deleting segment 0 (kafka.log.Log)}}
{{[2019-08-07 12:10:54,101] INFO Deleted log /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.log.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,101] INFO Deleted offset index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.index.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,101] INFO Deleted time index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.timeindex.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,173] INFO [Log partition=backup_br_domain_squad-14, dir=/var/lib/kafka/data/topics]
Deleting segment 0 (kafka.log.Log)}}
{{[2019-08-07 12:10:54,173] INFO Deleted log /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.log.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,173] INFO Deleted offset index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.index.deleted.
(kafka.log.LogSegment)}}
{{[2019-08-07 12:10:54,173] INFO Deleted time index /var/lib/kafka/data/topics/backup_br_domain_squad-14/00000000000000000000.timeindex.deleted.
(kafka.log.LogSegment)}}

 

And such log keeps repeating forever.

 

 

I've been able to extract segment files from (running) leader broker, and replicated same
behaviour locally.
h1.  
h1. *Reproduction setup:*
 * start single broker kafka_2.12-2.2.1
 * create topic
 ** {{./bin/kafka-topics.sh --bootstrap-server *__BOOTSTRAP_SERVER__*:9092 --create --topic
backup_br_domain_squad --partitions 1 --replication-factor 1 --config cleanup.policy=compact
--config min.compaction.lag.ms=86400000 --config min.cleanable.dirty.ratio=0.3}}
 * stop broker
 * copy segment files (attachment content, under segments) to backup_br_domain_squad-0 log
folder
 * rerun broker again

 

After rerun, fun starts with endless repeating logging outputs:

{{[2019-08-07 13:05:37,610] DEBUG Checking if log segment may be cleaned: log='backup_br_domain_squad-0'
segment.baseOffset=0 segment.largestTimestamp=1563203503987; now - compactionLag=1565096737609;
is uncleanable=false (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,610] DEBUG Finding range of cleanable offsets for log=backup_br_domain_squad-0
topicPartition=backup_br_domain_squad-0. Last clean offset=Some(0) now=1565183137609 =>
firstDirtyOffset=0 firstUncleanableOffset=233 activeSegment.baseOffset=233 (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,613] INFO Cleaner 0: Beginning cleaning of log backup_br_domain_squad-0.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,613] INFO Cleaner 0: Building offset map for backup_br_domain_squad-0...
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,628] INFO Cleaner 0: Building offset map for log backup_br_domain_squad-0
for 1 segments in offset range [0, 233). (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,643] INFO Cleaner 0: Offset map for log backup_br_domain_squad-0 complete.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,644] INFO Cleaner 0: Cleaning log backup_br_domain_squad-0 (cleaning
prior to Wed Aug 07 13:05:22 GMT 2019, discarding tombstones prior to Thu Jan 01 00:00:00
GMT 1970)... (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,645] DEBUG Loaded index file /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.index.cleaned
with maxEntries = 1310720, maxIndexSize = 10485760, entries = 0, lastOffset = 0, file position
= 0 (kafka.log.OffsetIndex)}}
{{[2019-08-07 13:05:37,646] DEBUG Loaded index file /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.timeindex.cleaned
with maxEntries = 873813, maxIndexSize = 10485760, entries = 0, lastOffset = TimestampOffset(-1,0),
file position = 0 (kafka.log.TimeIndex)}}
{{[2019-08-07 13:05:37,647] INFO Cleaner 0: Cleaning segment 0 in log backup_br_domain_squad-0
(largest timestamp Mon Jul 15 15:11:43 GMT 2019) into 0, retaining deletes. (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,656] DEBUG Resized /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.index.cleaned
to 32, position is 32 and limit is 32 (kafka.log.OffsetIndex)}}
{{[2019-08-07 13:05:37,657] DEBUG Resized /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.timeindex.cleaned
to 36, position is 36 and limit is 36 (kafka.log.TimeIndex)}}
{{[2019-08-07 13:05:37,669] INFO Cleaner 0: Swapping in cleaned segment LogSegment(baseOffset=0,
size=1044021) for segment(s) List(LogSegment(baseOffset=0, size=1044021)) in log Log(/runtime/logs/kafka_1/backup_br_domain_squad-0)
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,672] INFO [kafka-log-cleaner-thread-0]:}}
{{ Log cleaner thread 0 cleaned log backup_br_domain_squad-0 (dirty section = [0, 0])}}
{{ 1.0 MB of log processed in 0.1 seconds (17.2 MB/sec).}}
{{ Indexed 1.0 MB in 0.0 seconds (33.2 Mb/sec, 51.7% of total time)}}
{{ Buffer utilization: 0.0%}}
{{ Cleaned 1.0 MB in 0.0 seconds (35.6 Mb/sec, 48.3% of total time)}}
{{ Start size: 1.0 MB (231 messages)}}
{{ End size: 1.0 MB (231 messages)}}
{{ 0.0% size reduction (0.0% fewer messages)}}
{{ (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,676] DEBUG Checking if log segment may be cleaned: log='backup_br_domain_squad-0'
segment.baseOffset=0 segment.largestTimestamp=1563203503987; now - compactionLag=1565096737676;
is uncleanable=false (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,677] DEBUG Finding range of cleanable offsets for log=backup_br_domain_squad-0
topicPartition=backup_br_domain_squad-0. Last clean offset=Some(232) now=1565183137676 =>
firstDirtyOffset=232 firstUncleanableOffset=233 activeSegment.baseOffset=233 (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,677] INFO Cleaner 0: Beginning cleaning of log backup_br_domain_squad-0.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,678] INFO Cleaner 0: Building offset map for backup_br_domain_squad-0...
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,680] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,9082,ListenerName(INSIDE_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,680] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,9082,ListenerName(INSIDE_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,681] INFO Awaiting socket connections on s0.0.0.0:9092. (kafka.network.Acceptor)}}
{{[2019-08-07 13:05:37,681] INFO Awaiting socket connections on s0.0.0.0:9092. (kafka.network.Acceptor)}}
{{[2019-08-07 13:05:37,700] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,9092,ListenerName(OUTSIDE_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,700] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,9092,ListenerName(OUTSIDE_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,701] INFO Awaiting socket connections on s0.0.0.0:19092. (kafka.network.Acceptor)}}
{{[2019-08-07 13:05:37,701] INFO Cleaner 0: Building offset map for log backup_br_domain_squad-0
for 1 segments in offset range [232, 233). (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,701] INFO Awaiting socket connections on s0.0.0.0:19092. (kafka.network.Acceptor)}}
{{[2019-08-07 13:05:37,702] INFO Cleaner 0: Offset map for log backup_br_domain_squad-0 complete.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,702] INFO Cleaner 0: Cleaning log backup_br_domain_squad-0 (cleaning
prior to Wed Aug 07 13:05:22 GMT 2019, discarding tombstones prior to Tue Aug 06 13:05:22
GMT 2019)... (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,703] INFO [kafka-log-cleaner-thread-0]:}}
{{ Log cleaner thread 0 cleaned log backup_br_domain_squad-0 (dirty section = [232, 232])}}
{{ 0.0 MB of log processed in 0.0 seconds (0.0 MB/sec).}}
{{ Indexed 0.0 MB in 0.0 seconds (0.3 Mb/sec, 96.2% of total time)}}
{{ Buffer utilization: 0.0%}}
{{ Cleaned 0.0 MB in 0.0 seconds (0.0 Mb/sec, 3.8% of total time)}}
{{ Start size: 0.0 MB (0 messages)}}
{{ End size: 0.0 MB (0 messages)}}
{{ NaN% size reduction (NaN% fewer messages)}}
{{ (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,707] DEBUG Checking if log segment may be cleaned: log='backup_br_domain_squad-0'
segment.baseOffset=0 segment.largestTimestamp=1563203503987; now - compactionLag=1565096737707;
is uncleanable=false (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,708] DEBUG Finding range of cleanable offsets for log=backup_br_domain_squad-0
topicPartition=backup_br_domain_squad-0. Last clean offset=Some(0) now=1565183137707 =>
firstDirtyOffset=0 firstUncleanableOffset=233 activeSegment.baseOffset=233 (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,708] INFO Cleaner 0: Beginning cleaning of log backup_br_domain_squad-0.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,708] INFO Cleaner 0: Building offset map for backup_br_domain_squad-0...
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,719] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,19092,ListenerName(MAC_OS_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,719] INFO [SocketServer brokerId=1001] Created data-plane acceptor
and processors for endpoint : EndPoint(null,19092,ListenerName(MAC_OS_DOCKER),PLAINTEXT) (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,721] INFO Cleaner 0: Building offset map for log backup_br_domain_squad-0
for 1 segments in offset range [0, 233). (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,722] INFO [SocketServer brokerId=1001] Started 3 acceptor threads for
data-plane (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,722] INFO [SocketServer brokerId=1001] Started 3 acceptor threads for
data-plane (kafka.network.SocketServer)}}
{{[2019-08-07 13:05:37,730] INFO Cleaner 0: Offset map for log backup_br_domain_squad-0 complete.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,730] INFO Cleaner 0: Cleaning log backup_br_domain_squad-0 (cleaning
prior to Wed Aug 07 13:05:22 GMT 2019, discarding tombstones prior to Thu Jan 01 00:00:00
GMT 1970)... (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,732] DEBUG Loaded index file /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.index.cleaned
with maxEntries = 1310720, maxIndexSize = 10485760, entries = 0, lastOffset = 0, file position
= 0 (kafka.log.OffsetIndex)}}
{{[2019-08-07 13:05:37,733] DEBUG Loaded index file /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.timeindex.cleaned
with maxEntries = 873813, maxIndexSize = 10485760, entries = 0, lastOffset = TimestampOffset(-1,0),
file position = 0 (kafka.log.TimeIndex)}}
{{[2019-08-07 13:05:37,733] INFO Cleaner 0: Cleaning segment 0 in log backup_br_domain_squad-0
(largest timestamp Mon Jul 15 15:11:43 GMT 2019) into 0, retaining deletes. (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,739] DEBUG Resized /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.index.cleaned
to 32, position is 32 and limit is 32 (kafka.log.OffsetIndex)}}
{{[2019-08-07 13:05:37,739] DEBUG Resized /runtime/logs/kafka_1/backup_br_domain_squad-0/00000000000000000000.timeindex.cleaned
to 36, position is 36 and limit is 36 (kafka.log.TimeIndex)}}
{{[2019-08-07 13:05:37,764] INFO Cleaner 0: Swapping in cleaned segment LogSegment(baseOffset=0,
size=1044021) for segment(s) List(LogSegment(baseOffset=0, size=1044021)) in log Log(/runtime/logs/kafka_1/backup_br_domain_squad-0)
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,767] INFO [kafka-log-cleaner-thread-0]:}}
{{ Log cleaner thread 0 cleaned log backup_br_domain_squad-0 (dirty section = [0, 0])}}
{{ 1.0 MB of log processed in 0.1 seconds (17.2 MB/sec).}}
{{ Indexed 1.0 MB in 0.0 seconds (45.3 Mb/sec, 37.9% of total time)}}
{{ Buffer utilization: 0.0%}}
{{ Cleaned 1.0 MB in 0.0 seconds (27.7 Mb/sec, 62.1% of total time)}}
{{ Start size: 1.0 MB (231 messages)}}
{{ End size: 1.0 MB (231 messages)}}
{{ 0.0% size reduction (0.0% fewer messages)}}
{{ (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,772] DEBUG Checking if log segment may be cleaned: log='backup_br_domain_squad-0'
segment.baseOffset=0 segment.largestTimestamp=1563203503987; now - compactionLag=1565096737771;
is uncleanable=false (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,772] DEBUG Finding range of cleanable offsets for log=backup_br_domain_squad-0
topicPartition=backup_br_domain_squad-0. Last clean offset=Some(232) now=1565183137771 =>
firstDirtyOffset=232 firstUncleanableOffset=233 activeSegment.baseOffset=233 (kafka.log.LogCleanerManager$)}}
{{[2019-08-07 13:05:37,773] INFO Cleaner 0: Beginning cleaning of log backup_br_domain_squad-0.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,774] INFO Cleaner 0: Building offset map for backup_br_domain_squad-0...
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,795] INFO [ExpirationReaper-1001-Produce]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,795] INFO [ExpirationReaper-1001-Produce]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,800] INFO [ExpirationReaper-1001-Fetch]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,800] INFO [ExpirationReaper-1001-Fetch]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,803] INFO [ExpirationReaper-1001-DeleteRecords]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,803] INFO [ExpirationReaper-1001-DeleteRecords]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,805] INFO [ExpirationReaper-1001-ElectPreferredLeader]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,805] INFO [ExpirationReaper-1001-ElectPreferredLeader]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)}}
{{[2019-08-07 13:05:37,806] INFO Cleaner 0: Building offset map for log backup_br_domain_squad-0
for 1 segments in offset range [232, 233). (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,807] INFO Cleaner 0: Offset map for log backup_br_domain_squad-0 complete.
(kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,808] INFO Cleaner 0: Cleaning log backup_br_domain_squad-0 (cleaning
prior to Wed Aug 07 13:05:22 GMT 2019, discarding tombstones prior to Tue Aug 06 13:05:22
GMT 2019)... (kafka.log.LogCleaner)}}
{{[2019-08-07 13:05:37,809] INFO [kafka-log-cleaner-thread-0]:}}
{{ Log cleaner thread 0 cleaned log backup_br_domain_squad-0 (dirty section = [232, 232])}}
{{ 0.0 MB of log processed in 0.0 seconds (0.0 MB/sec).}}
{{ Indexed 0.0 MB in 0.0 seconds (0.2 Mb/sec, 97.1% of total time)}}
{{ Buffer utilization: 0.0%}}
{{ Cleaned 0.0 MB in 0.0 seconds (0.0 Mb/sec, 2.9% of total time)}}
{{ Start size: 0.0 MB (0 messages)}}
{{ End size: 0.0 MB (0 messages)}}
{{ NaN% size reduction (NaN% fewer messages)}}
{{ (kafka.log.LogCleaner)}}

 

 



--
This message was sent by Atlassian JIRA
(v7.6.14#76016)

Mime
View raw message