KAFKA-16446: Improve controller event duration logging #15622
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,212 @@ | ||
| /* | ||
| * Licensed to the Apache Software Foundation (ASF) under one or more | ||
| * contributor license agreements. See the NOTICE file distributed with | ||
| * this work for additional information regarding copyright ownership. | ||
| * The ASF licenses this file to You under the Apache License, Version 2.0 | ||
| * (the "License"); you may not use this file except in compliance with | ||
| * the License. You may obtain a copy of the License at | ||
| * | ||
| * http://www.apache.org/licenses/LICENSE-2.0 | ||
| * | ||
| * Unless required by applicable law or agreed to in writing, software | ||
| * distributed under the License is distributed on an "AS IS" BASIS, | ||
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | ||
| * See the License for the specific language governing permissions and | ||
| * limitations under the License. | ||
| */ | ||
|
|
||
| package org.apache.kafka.controller; | ||
|
|
||
| import org.apache.kafka.common.utils.LogContext; | ||
|
|
||
| import org.slf4j.Logger; | ||
|
|
||
| import java.text.DecimalFormat; | ||
| import java.util.AbstractMap; | ||
| import java.util.Map; | ||
|
|
||
| import static java.util.concurrent.TimeUnit.NANOSECONDS; | ||
| import static java.util.concurrent.TimeUnit.SECONDS; | ||
|
|
||
| /** | ||
| * Track the performance of controller events. Periodically log the slowest events. | ||
| * Log any event slower than a certain threshold. | ||
| */ | ||
| class EventPerformanceMonitor { | ||
| /** | ||
| * The format to use when displaying milliseconds. | ||
| */ | ||
| private static final DecimalFormat MILLISECOND_DECIMAL_FORMAT = new DecimalFormat("#0.00"); | ||
|
|
||
| static class Builder { | ||
| LogContext logContext = null; | ||
| long periodNs = SECONDS.toNanos(60); | ||
| long alwaysLogThresholdNs = SECONDS.toNanos(2); | ||
|
|
||
| Builder setLogContext(LogContext logContext) { | ||
| this.logContext = logContext; | ||
| return this; | ||
| } | ||
|
|
||
| Builder setPeriodNs(long periodNs) { | ||
| this.periodNs = periodNs; | ||
| return this; | ||
| } | ||
|
|
||
| Builder setAlwaysLogThresholdNs(long alwaysLogThresholdNs) { | ||
| this.alwaysLogThresholdNs = alwaysLogThresholdNs; | ||
| return this; | ||
| } | ||
|
|
||
| EventPerformanceMonitor build() { | ||
| if (logContext == null) logContext = new LogContext(); | ||
| return new EventPerformanceMonitor(logContext, | ||
| periodNs, | ||
| alwaysLogThresholdNs); | ||
| } | ||
| } | ||
|
|
||
| /** | ||
| * The log4j object to use. | ||
| */ | ||
| private final Logger log; | ||
|
|
||
| /** | ||
| * The period in nanoseconds. | ||
| */ | ||
| private long periodNs; | ||
|
|
||
| /** | ||
| * The always-log threshold in nanoseconds. | ||
| */ | ||
| private long alwaysLogThresholdNs; | ||
|
|
||
| /** | ||
| * The name of the slowest event we've seen so far, or null if none has been seen. | ||
| */ | ||
| private String slowestEventName; | ||
|
|
||
| /** | ||
| * The duration of the slowest event we've seen so far, or 0 if none has been seen. | ||
| */ | ||
| private long slowestEventDurationNs; | ||
|
|
||
| /** | ||
| * The total duration of all the events we've seen. | ||
| */ | ||
| private long totalEventDurationNs; | ||
|
Member
Author
There was a problem hiding this comment. Recording this is interesting. Since we have a single controller thread and can see its total event duration over a fixed period, we could calculate the idle percentage of the controller. Might be interesting to look at as a high level "busy" metric
Contributor
There was a problem hiding this comment. Yeah, that might be interesting. It would probably be better to get idle numbers directly from the queue somehow (since it knows how long it waited...) just to avoid errors adding up over time. |
||
|
|
||
| /** | ||
| * The number of events we've seen. | ||
| */ | ||
| private int numEvents; | ||
|
|
||
| private EventPerformanceMonitor( | ||
| LogContext logContext, | ||
| long periodNs, | ||
| long alwaysLogThresholdNs | ||
| ) { | ||
| this.log = logContext.logger(EventPerformanceMonitor.class); | ||
| this.periodNs = periodNs; | ||
| this.alwaysLogThresholdNs = alwaysLogThresholdNs; | ||
| reset(); | ||
| } | ||
|
|
||
| long periodNs() { | ||
| return periodNs; | ||
| } | ||
|
|
||
| Map.Entry<String, Long> slowestEvent() { | ||
| return new AbstractMap.SimpleImmutableEntry<>(slowestEventName, slowestEventDurationNs); | ||
| } | ||
|
|
||
| /** | ||
| * Reset all internal state. | ||
| */ | ||
| void reset() { | ||
| this.slowestEventName = null; | ||
| this.slowestEventDurationNs = 0; | ||
| this.totalEventDurationNs = 0; | ||
| this.numEvents = 0; | ||
| } | ||
|
|
||
| /** | ||
| * Handle a controller event being finished. | ||
| * | ||
| * @param name The name of the controller event. | ||
| * @param durationNs The duration of the controller event in nanoseconds. | ||
| */ | ||
| void observeEvent(String name, long durationNs) { | ||
| String message = doObserveEvent(name, durationNs); | ||
| if (message != null) { | ||
| log.error("{}", message); | ||
| } | ||
| } | ||
|
|
||
| /** | ||
| * Handle a controller event being finished. | ||
| * | ||
| * @param name The name of the controller event. | ||
| * @param durationNs The duration of the controller event in nanoseconds. | ||
| * | ||
| * @return The message to log, or null otherwise. | ||
| */ | ||
| String doObserveEvent(String name, long durationNs) { | ||
| if (slowestEventName == null || slowestEventDurationNs < durationNs) { | ||
| slowestEventName = name; | ||
| slowestEventDurationNs = durationNs; | ||
| } | ||
| totalEventDurationNs += durationNs; | ||
| numEvents++; | ||
| if (durationNs < alwaysLogThresholdNs) { | ||
| return null; | ||
| } | ||
| return "Exceptionally slow controller event " + name + " took " + | ||
| NANOSECONDS.toMillis(durationNs) + " ms."; | ||
| } | ||
|
|
||
| /** | ||
| * Generate a log message summarizing the events of the last period, | ||
| * and then reset our internal state. | ||
| */ | ||
| void generatePeriodicPerformanceMessage() { | ||
| String message = periodicPerformanceMessage(); | ||
| log.info("{}", message); | ||
| reset(); | ||
| } | ||
|
|
||
| /** | ||
| * Generate a log message summarizing the events of the last period. | ||
| * | ||
| * @return The summary string. | ||
| */ | ||
| String periodicPerformanceMessage() { | ||
| StringBuilder bld = new StringBuilder(); | ||
| bld.append("In the last "); | ||
| bld.append(NANOSECONDS.toMillis(periodNs)); | ||
| bld.append(" ms period, "); | ||
| if (numEvents == 0) { | ||
| bld.append("there were no controller events completed."); | ||
| } else { | ||
| bld.append(numEvents).append(" controller events were completed, which took an average of "); | ||
| bld.append(nanosecondsToDecimalMillis(totalEventDurationNs / numEvents)); | ||
| bld.append(" ms each. The slowest event was ").append(slowestEventName); | ||
| bld.append(", which took "); | ||
| bld.append(nanosecondsToDecimalMillis(slowestEventDurationNs)); | ||
| bld.append(" ms."); | ||
| } | ||
| return bld.toString(); | ||
| } | ||
|
|
||
| /** | ||
| * Translate a duration in nanoseconds to a decimal duration in milliseconds. | ||
| * | ||
| * @param durationNs The duration in nanoseconds. | ||
| * @return The decimal duration in milliseconds. | ||
| */ | ||
| static String nanosecondsToDecimalMillis(long durationNs) { | ||
|
Member
Author
There was a problem hiding this comment. naming: maybe "formatNanosAsMillis" or something with "format" in the name? |
||
| double number = NANOSECONDS.toMicros(durationNs); | ||
| number /= 1000; | ||
| return MILLISECOND_DECIMAL_FORMAT.format(number); | ||
| } | ||
| } | ||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
One reason I didn't go with a fixed threshold originally was that I was concerned about a negative feedback loop with a congested controller. For example, if all the events on the controller are above this threshold due to some bug or external influence, doing the extra logging just makes things worse.
However, thinking about it more, maybe the extra logging wouldn't be such a hit. If the controller is congested and the threshold is a few seconds, then the extra few ms to do logging wouldn't change the situation much.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Right. Once you're at 2 seconds per event, another log message isn't going to change much. Also, I hope we're logging in less than a few ms, although with these logging libraries, ya never know...