From 73918f21d2d3ff5cc632c0837a0266a5f1ed384b Mon Sep 17 00:00:00 2001
From: Allen Wang <allenwang@linkedin.com>
Date: Tue, 1 Oct 2024 13:15:39 -0700
Subject: [PATCH] Add more logging to help debugging the time spent on goal
 based operation

---
 .../async/progress/OperationProgress.java     | 20 +++++++++++++++++++
 .../cruisecontrol/executor/Executor.java      |  3 +++
 .../runnable/GoalBasedOperationRunnable.java  |  8 ++++++++
 3 files changed, 31 insertions(+)

diff --git a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/async/progress/OperationProgress.java b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/async/progress/OperationProgress.java
index 713de400ec..c6be270217 100644
--- a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/async/progress/OperationProgress.java
+++ b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/async/progress/OperationProgress.java
@@ -100,6 +100,26 @@ public synchronized String toString() {
     return sb.toString();
   }
 
+  /**
+   * @return the up-to-date total execution time on the progress
+   */
+  public synchronized long getCurrentTotalExecutionTime() {
+    if (_startTimes.isEmpty()) {
+      return 0;
+    } else {
+      long currentTime = System.currentTimeMillis();
+      long startTime = _startTimes.get(0);
+      return currentTime - startTime;
+    }
+  }
+
+  /**
+   * @return the name of the operation
+   */
+  public String getOperation() {
+    return _operation;
+  }
+
   /**
    * @return The map describing the progress of the operation.
    */
diff --git a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/executor/Executor.java b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/executor/Executor.java
index 98aad37be5..d8956bfbeb 100644
--- a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/executor/Executor.java
+++ b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/executor/Executor.java
@@ -832,6 +832,9 @@ public synchronized void executeProposals(Collection<ExecutionProposal> proposal
                             isTriggeredByUserRequest, loadMonitor);
       startExecution(loadMonitor, null, removedBrokers, replicationThrottle, isTriggeredByUserRequest);
     } catch (Exception e) {
+      if (e instanceof OngoingExecutionException) {
+        LOG.info("Broker removal operation with uuid {} aborted due to ongoing execution", uuid);
+      }
       processExecuteProposalsFailure();
       throw e;
     }
diff --git a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/servlet/handler/async/runnable/GoalBasedOperationRunnable.java b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/servlet/handler/async/runnable/GoalBasedOperationRunnable.java
index 688f14066f..7d5c03c971 100644
--- a/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/servlet/handler/async/runnable/GoalBasedOperationRunnable.java
+++ b/cruise-control/src/main/java/com/linkedin/kafka/cruisecontrol/servlet/handler/async/runnable/GoalBasedOperationRunnable.java
@@ -17,6 +17,8 @@
 import java.util.concurrent.TimeoutException;
 import java.util.function.Supplier;
 import java.util.regex.Pattern;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import static com.linkedin.kafka.cruisecontrol.KafkaCruiseControlUtils.goalsByPriority;
 import static com.linkedin.kafka.cruisecontrol.KafkaCruiseControlUtils.sanityCheckGoals;
@@ -34,6 +36,7 @@
  * An abstract class to extract the common logic of goal based operation runnables.
  */
 public abstract class GoalBasedOperationRunnable extends OperationRunnable {
+  private static final Logger LOG = LoggerFactory.getLogger(GoalBasedOperationRunnable.class);
   protected final List<String> _goals;
   protected final ModelCompletenessRequirements _modelCompletenessRequirements;
   protected final boolean _dryRun;
@@ -207,6 +210,11 @@ protected abstract OptimizerResult workWithClusterModel()
    * Perform the memory clean up after {@link #computeResult()}.
    */
   protected void finish() {
+    if (_operationProgress != null) {
+      long totalTime = _operationProgress.getCurrentTotalExecutionTime();
+      LOG.info("Operation {} finished with uuid {}; total time: {}ms; steps: {}",
+          _operationProgress.getOperation(), _uuid, totalTime, _operationProgress);
+    }
     _operationProgress = null;
     _combinedCompletenessRequirements = null;
     if (_goalsByPriority != null) {