Skip to content

allocation: add timing and iteration to logging #139150

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
schase-es wants to merge 1 commit into
base: main
Choose a base branch
from
+71 −41
Open

allocation: add timing and iteration to logging #139150

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
38 changes: 24 additions & 14 deletions ...n/java/org/elasticsearch/cluster/routing/allocation/allocator/DesiredBalanceComputer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -403,24 +403,29 @@ public DesiredBalance compute(
convergenceLogMsgLevel,
() -> Strings.format(
"""
Desired balance computation for [%d] converged after [%s] and [%d] iterations, \
resumed computation [%d] times with [%d] iterations since the last resumption [%s] ago""",
Desired balance computation for [%d] converged after [%s] and [%d] iterations this round, \
Copy link
Contributor

@DaveCTurner DaveCTurner Dec 5, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the total time & number of iterations is more important than the number since it was last interrupted - could we reverse the order so that the total numbers come first?

resumed computation [%s] ago with [%d] iterations over [%d] rounds since the last convergence \
[%s] ago""",
desiredBalanceInput.index(),
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString(),
iterations,
TimeValue.timeValueMillis(currentTime - firstComputeStartedSinceConvergedTimeMillis).toString(),
numIterationsSinceLastConverged,
numComputeCallsSinceLastConverged,
iterations,
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString()
TimeValue.timeValueMillis(currentTime - lastConvergedTimeMillis).toString()
)
);
} else {
logger.log(
convergenceLogMsgLevel,
() -> Strings.format(
"Desired balance computation for [%d] converged after [%s] and [%d] iterations",
"""
Desired balance computation for [%d] converged after [%s] and [%d] iterations this round, \
Copy link
Contributor

@DaveCTurner DaveCTurner Dec 5, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"this round" implies there have been other rounds, but that's not the case here. Maybe "in a single round" would be clearer?

last convergence was [%s] ago""",
desiredBalanceInput.index(),
TimeValue.timeValueMillis(currentTime - firstComputeStartedSinceConvergedTimeMillis).toString(),
numIterationsSinceLastConverged
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString(),
iterations,
TimeValue.timeValueMillis(currentTime - lastConvergedTimeMillis).toString()
)
);
}
Expand Down Expand Up @@ -465,24 +470,29 @@ public DesiredBalance compute(
logLevel,
() -> Strings.format(
"""
Desired balance computation for [%d] is still not converged after [%s] and [%d] iterations, \
resumed computation [%d] times with [%d] iterations since the last resumption [%s] ago""",
Desired balance computation for [%d] is still not converged after [%s] and [%d] iterations this round, \
resumed computation [%s] ago with [%d] iterations over [%d] rounds since the last convergence \
[%s] ago""",
desiredBalanceInput.index(),
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString(),
iterations,
TimeValue.timeValueMillis(currentTime - firstComputeStartedSinceConvergedTimeMillis).toString(),
numIterationsSinceLastConverged,
numComputeCallsSinceLastConverged,
iterations,
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString()
TimeValue.timeValueMillis(currentTime - lastConvergedTimeMillis).toString()
)
);
} else {
logger.log(
logLevel,
() -> Strings.format(
"Desired balance computation for [%d] is still not converged after [%s] and [%d] iterations",
"""
Desired balance computation for [%d] is still not converged after [%s] and [%d] iterations this round, \
last convergence was [%s] ago""",
desiredBalanceInput.index(),
TimeValue.timeValueMillis(currentTime - firstComputeStartedSinceConvergedTimeMillis).toString(),
numIterationsSinceLastConverged
TimeValue.timeValueMillis(currentTime - computationStartedTime).toString(),
iterations,
TimeValue.timeValueMillis(currentTime - lastConvergedTimeMillis).toString()
)
);
}
Expand Down
74 changes: 47 additions & 27 deletions ...a/org/elasticsearch/cluster/routing/allocation/allocator/DesiredBalanceComputerTests.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1453,7 +1453,7 @@ public void testShouldLogComputationIteration() {
"Should report long computation based on iteration count",
DesiredBalanceComputer.class.getCanonicalName(),
Level.INFO,
"Desired balance computation for [*] is still not converged after [10s] and [1000] iterations"
"Desired balance computation for [*] is still not converged after [10s] and [1000] iterations *"
)
);

Expand All @@ -1464,7 +1464,7 @@ public void testShouldLogComputationIteration() {
"Should report long computation based on time",
DesiredBalanceComputer.class.getCanonicalName(),
Level.INFO,
"Desired balance computation for [*] is still not converged after [1m] and [60] iterations"
"Desired balance computation for [*] is still not converged after [1m] and [60] iterations *"
)
);
}
Expand Down Expand Up @@ -1562,36 +1562,44 @@ record ExpectedLastConvergenceInfo(int numComputeCalls, int numTotalIterations,

record LogExpectationData(
boolean isConverged,
String timeSinceConverged,
String currentDuration,
int currentIterations,
String timeSinceRecompute,
int totalIterations,
int totalComputeCalls,
int currentIterations,
String currentDuration
String timeSinceConverged
) {
LogExpectationData(boolean isConverged, String timeSinceConverged, int totalIterations) {
this(isConverged, timeSinceConverged, totalIterations, 0, 0, "");
LogExpectationData(boolean isConverged, String currentDuration, int currentIterations, String timeSinceConverged) {
this(isConverged, currentDuration, currentIterations, "", 0, 0, timeSinceConverged);
}
}

Function<LogExpectationData, MockLog.SeenEventExpectation> getLogExpectation = data -> {
final var singleComputeCallMsg = "Desired balance computation for [%d] "
final var message = "Desired balance computation for [%d] "
+ (data.isConverged ? "" : "is still not ")
+ "converged after [%s] and [%d] iterations";
+ "converged after [%s] and [%d] iterations this round, ";
return new MockLog.SeenEventExpectation(
"expected a " + (data.isConverged ? "converged" : "not converged") + " log message",
DesiredBalanceComputer.class.getCanonicalName(),
Level.INFO,
(data.totalComputeCalls > 1
? Strings.format(
singleComputeCallMsg + ", resumed computation [%d] times with [%d] iterations since the last resumption [%s] ago",
message + "resumed computation [%s] ago with [%d] iterations over [%d] rounds since the last convergence [%s] ago",
indexSequence.get(),
data.timeSinceConverged,
data.currentDuration,
data.currentIterations,
data.timeSinceRecompute,
data.totalIterations,
data.totalComputeCalls,
data.currentIterations,
data.currentDuration
data.timeSinceConverged
)
: Strings.format(singleComputeCallMsg, indexSequence.get(), data.timeSinceConverged, data.totalIterations))
: Strings.format(
message + "last convergence was [%s] ago",
indexSequence.get(),
data.currentDuration,
data.currentIterations,
data.timeSinceConverged
))
);
};

Expand All @@ -1609,7 +1617,7 @@ record LogExpectationData(
// Converges right away, verify the debug level convergence message.
assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> true),
getLogExpectation.apply(new LogExpectationData(true, "2ms", 2))
getLogExpectation.apply(new LogExpectationData(true, "2ms", 2, "3ms"))
);
assertFinishReason.accept(DesiredBalance.ComputationFinishReason.CONVERGED);
final var lastConvergenceTimestampMillis = computer.getLastConvergedTimeMillis();
Expand All @@ -1620,7 +1628,7 @@ record LogExpectationData(
// This INFO is triggered from the interval since last convergence timestamp.
assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> iterationCounter.get() < 6),
getLogExpectation.apply(new LogExpectationData(false, "5ms", 5))
getLogExpectation.apply(new LogExpectationData(false, "5ms", 5, "6ms"))
);
assertFinishReason.accept(DesiredBalance.ComputationFinishReason.YIELD_TO_NEW_INPUT);
assertLastConvergenceInfo.accept(new ExpectedLastConvergenceInfo(1, 6, lastConvergenceTimestampMillis));
Expand All @@ -1629,26 +1637,26 @@ record LogExpectationData(
// The next INFO is triggered from the interval since last INFO message logged, and then another after the interval period.
assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> iterationCounter.get() < 9),
getLogExpectation.apply(new LogExpectationData(false, "10ms", 9, 2, 3, "3ms")),
getLogExpectation.apply(new LogExpectationData(false, "15ms", 14, 2, 8, "8ms"))
getLogExpectation.apply(new LogExpectationData(false, "3ms", 3, "10ms", 9, 2, "11ms")),
getLogExpectation.apply(new LogExpectationData(false, "8ms", 8, "15ms", 14, 2, "16ms"))
);
assertFinishReason.accept(DesiredBalance.ComputationFinishReason.YIELD_TO_NEW_INPUT);
assertLastConvergenceInfo.accept(new ExpectedLastConvergenceInfo(2, 15, lastConvergenceTimestampMillis));

assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> true),
getLogExpectation.apply(new LogExpectationData(false, "20ms", 18, 3, 3, "3ms")),
getLogExpectation.apply(new LogExpectationData(false, "25ms", 23, 3, 8, "8ms")),
getLogExpectation.apply(new LogExpectationData(true, "29ms", 27, 3, 12, "12ms"))
getLogExpectation.apply(new LogExpectationData(false, "3ms", 3, "20ms", 18, 3, "21ms")),
getLogExpectation.apply(new LogExpectationData(false, "8ms", 8, "25ms", 23, 3, "26ms")),
getLogExpectation.apply(new LogExpectationData(true, "12ms", 12, "29ms", 27, 3, "30ms"))
);
assertFinishReason.accept(DesiredBalance.ComputationFinishReason.CONVERGED);

// First INFO is triggered from interval since last converged, second is triggered from the inverval since the last INFO log.
assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> true),
getLogExpectation.apply(new LogExpectationData(false, "5ms", 5)),
getLogExpectation.apply(new LogExpectationData(false, "10ms", 10)),
getLogExpectation.apply(new LogExpectationData(true, "12ms", 12))
getLogExpectation.apply(new LogExpectationData(false, "5ms", 5, "6ms")),
getLogExpectation.apply(new LogExpectationData(false, "10ms", 10, "11ms")),
getLogExpectation.apply(new LogExpectationData(true, "12ms", 12, "13ms"))
);
assertFinishReason.accept(DesiredBalance.ComputationFinishReason.CONVERGED);

Expand All @@ -1663,7 +1671,7 @@ record LogExpectationData(
requiredIterations.set(2);
assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> iterationCounter.get() < 2),
getLogExpectation.apply(new LogExpectationData(true, "2ms", 2))
getLogExpectation.apply(new LogExpectationData(true, "2ms", 2, "103ms"))
);

// test a non-convergence and convergence message with a significant time delta,
Expand All @@ -1675,8 +1683,20 @@ record LogExpectationData(

assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> true),
getLogExpectation.apply(new LogExpectationData(false, "103ms", 2, 2, 1, "1ms")),
getLogExpectation.apply(new LogExpectationData(true, "104ms", 3, 2, 2, "2ms"))
getLogExpectation.apply(new LogExpectationData(false, "1ms", 1, "103ms", 2, 2, "204ms")),
getLogExpectation.apply(new LogExpectationData(true, "2ms", 2, "104ms", 3, 2, "205ms"))
);

// similarly, test the time-since-convergence and time-since-compute for logging
// caused by intervals instead of iterations
iterationCounter.set(0);
requiredIterations.set(6);
timeInMillis.addAndGet(100L);

assertLoggerExpectationsFor(
getComputeRunnableForIsFreshPredicate.apply(ignored -> true),
getLogExpectation.apply(new LogExpectationData(false, "5ms", 5, "106ms")),
getLogExpectation.apply(new LogExpectationData(true, "6ms", 6, "107ms"))
);
}

Expand Down