From f8acfa5257f6ba6c229884b638053d52b1b3e68a Mon Sep 17 00:00:00 2001 From: David Jacot Date: Thu, 26 Sep 2024 20:00:44 +0200 Subject: [PATCH] KAFKA-17621; Reduce logging verbosity on ConsumerGroupHeartbeat path (#17288) While running large scale performance tests, we noticed that the logging on the ConsumerGroupHeartbeat path took a significant amount of CPU. It is mainly due to the very large data structures that we print out. I made a pass on those logs and I switched some of them to debug. Reviewers: Lianet Magrans --- .../group/GroupMetadataManager.java | 41 ++++++++++++------- 1 file changed, 27 insertions(+), 14 deletions(-) diff --git a/group-coordinator/src/main/java/org/apache/kafka/coordinator/group/GroupMetadataManager.java b/group-coordinator/src/main/java/org/apache/kafka/coordinator/group/GroupMetadataManager.java index b367009a621..384c5295c97 100644 --- a/group-coordinator/src/main/java/org/apache/kafka/coordinator/group/GroupMetadataManager.java +++ b/group-coordinator/src/main/java/org/apache/kafka/coordinator/group/GroupMetadataManager.java @@ -1793,8 +1793,10 @@ public class GroupMetadataManager { ); if (!subscriptionMetadata.equals(group.subscriptionMetadata())) { - log.info("[GroupId {}] Computed new subscription metadata: {}.", - groupId, subscriptionMetadata); + if (log.isDebugEnabled()) { + log.debug("[GroupId {}] Computed new subscription metadata: {}.", + groupId, subscriptionMetadata); + } bumpGroupEpoch = true; records.add(newConsumerGroupSubscriptionMetadataRecord(groupId, subscriptionMetadata)); } @@ -1984,8 +1986,10 @@ public class GroupMetadataManager { ); if (!subscriptionMetadata.equals(group.subscriptionMetadata())) { - log.info("[GroupId {}] Computed new subscription metadata: {}.", - groupId, subscriptionMetadata); + if (log.isDebugEnabled()) { + log.debug("[GroupId {}] Computed new subscription metadata: {}.", + groupId, subscriptionMetadata); + } bumpGroupEpoch = true; records.add(newConsumerGroupSubscriptionMetadataRecord(groupId, subscriptionMetadata)); } @@ -2350,13 +2354,13 @@ public class GroupMetadataManager { records.add(newConsumerGroupMemberSubscriptionRecord(groupId, updatedMember)); if (!updatedMember.subscribedTopicNames().equals(member.subscribedTopicNames())) { - log.info("[GroupId {}] Member {} updated its subscribed topics to: {}.", + log.debug("[GroupId {}] Member {} updated its subscribed topics to: {}.", groupId, memberId, updatedMember.subscribedTopicNames()); return true; } if (!updatedMember.subscribedTopicRegex().equals(member.subscribedTopicRegex())) { - log.info("[GroupId {}] Member {} updated its subscribed regex to: {}.", + log.debug("[GroupId {}] Member {} updated its subscribed regex to: {}.", groupId, memberId, updatedMember.subscribedTopicRegex()); return true; } @@ -2432,10 +2436,12 @@ public class GroupMetadataManager { if (!updatedMember.equals(member)) { records.add(newConsumerGroupCurrentAssignmentRecord(groupId, updatedMember)); - log.info("[GroupId {}] Member {} new assignment state: epoch={}, previousEpoch={}, state={}, " - + "assignedPartitions={} and revokedPartitions={}.", - groupId, updatedMember.memberId(), updatedMember.memberEpoch(), updatedMember.previousMemberEpoch(), updatedMember.state(), - assignmentToString(updatedMember.assignedPartitions()), assignmentToString(updatedMember.partitionsPendingRevocation())); + if (log.isDebugEnabled()) { + log.debug("[GroupId {}] Member {} new assignment state: epoch={}, previousEpoch={}, state={}, " + + "assignedPartitions={} and revokedPartitions={}.", + groupId, updatedMember.memberId(), updatedMember.memberEpoch(), updatedMember.previousMemberEpoch(), updatedMember.state(), + assignmentToString(updatedMember.assignedPartitions()), assignmentToString(updatedMember.partitionsPendingRevocation())); + } // Schedule/cancel the rebalance timeout if the member uses the consumer protocol. // The members using classic protocol only have join timer and sync timer. @@ -2543,8 +2549,13 @@ public class GroupMetadataManager { assignmentResultBuilder.build(); long assignorTimeMs = time.milliseconds() - startTimeMs; - log.info("[GroupId {}] Computed a new target assignment for epoch {} with '{}' assignor in {}ms: {}.", - group.groupId(), groupEpoch, preferredServerAssignor, assignorTimeMs, assignmentResult.targetAssignment()); + if (log.isDebugEnabled()) { + log.debug("[GroupId {}] Computed a new target assignment for epoch {} with '{}' assignor in {}ms: {}.", + group.groupId(), groupEpoch, preferredServerAssignor, assignorTimeMs, assignmentResult.targetAssignment()); + } else { + log.info("[GroupId {}] Computed a new target assignment for epoch {} with '{}' assignor in {}ms.", + group.groupId(), groupEpoch, preferredServerAssignor, assignorTimeMs); + } records.addAll(assignmentResult.records()); @@ -2741,8 +2752,10 @@ public class GroupMetadataManager { ); if (!subscriptionMetadata.equals(group.subscriptionMetadata())) { - log.info("[GroupId {}] Computed new subscription metadata: {}.", - group.groupId(), subscriptionMetadata); + if (log.isDebugEnabled()) { + log.debug("[GroupId {}] Computed new subscription metadata: {}.", + group.groupId(), subscriptionMetadata); + } records.add(newConsumerGroupSubscriptionMetadataRecord(group.groupId(), subscriptionMetadata)); }