CNDB-16237: Add execution info to logs about aborted queries

src/java/org/apache/cassandra/config/CassandraRelevantProperties.java

@@ -384,19 +384,19 @@ public enum CassandraRelevantProperties
     CUSTOM_SSTABLE_WATCHER("cassandra.custom_sstable_watcher"),
 
     /** Defines the interval for reporting any operations that have timed out.  */
-    SLOW_QUERY_LOG_MONITORING_REPORT_INTERVAL_IN_MS("cassandra.monitoring_report_interval_ms", "5000"),
+    MONITORING_REPORT_INTERVAL_MS("cassandra.monitoring_report_interval_ms", "5000"),
 
     /**
      * Defines the maximum number of unique timed out queries that will be reported in the logs.
      * Use a negative number to remove any limit.
      */
-    SLOW_QUERY_LOG_MONITORING_MAX_OPERATIONS("cassandra.monitoring_max_operations", "50"),
+    MONITORING_MAX_OPERATIONS("cassandra.monitoring_max_operations", "50"),
 
     /**
      * Whether to log detailed execution info when logging slow non-SAI queries.
-     * For SAI queries, see {@link #SAI_SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED}.
+     * For SAI queries, see {@link #SAI_MONITORING_EXECUTION_INFO_ENABLED}.
      */
-    SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED("cassandra.monitoring_execution_info_enabled", "true"),
+    MONITORING_EXECUTION_INFO_ENABLED("cassandra.monitoring_execution_info_enabled", "true"),
 
     /** The current version of the SAI on-disk index format. */
     SAI_CURRENT_VERSION("cassandra.sai.latest.version", "ec"),
@@ -425,9 +425,9 @@ public enum CassandraRelevantProperties
     /**
      * Whether to log SAI-specific detailed execution info when logging slow SAI queries.
      * This execution info includes the query metrics and the query plan of the slow queries.
-     * For non-SAI queries, see {@link #SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED}.
+     * For non-SAI queries, see {@link #MONITORING_EXECUTION_INFO_ENABLED}.
      */
-    SAI_SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED("cassandra.sai.slow_query_log.execution_info_enabled", "true"),
+    SAI_MONITORING_EXECUTION_INFO_ENABLED("cassandra.sai.monitoring_execution_info_enabled", "true"),
 
     /** Whether vector type only allows float vectors. True by default. **/
     VECTOR_FLOAT_ONLY("cassandra.float_only_vectors", "true"),

src/java/org/apache/cassandra/db/ReadCommand.java

@@ -1137,7 +1137,7 @@ private ReadCommandExecutionInfo setupExecutionInfo(Index.Searcher searcher)
         }
 
         // if execution info is disabled, return null so we will keep using the default empty supplier
-        if (!CassandraRelevantProperties.SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED.getBoolean())
+        if (!CassandraRelevantProperties.MONITORING_EXECUTION_INFO_ENABLED.getBoolean())
             return null;
 
         // otherwise, create and use the generic execution info

src/java/org/apache/cassandra/db/monitoring/MonitoringTask.java

@@ -55,8 +55,8 @@ public class MonitoringTask
     private static final NoSpamLogger noSpamLogger = NoSpamLogger.getLogger(logger, 5L, TimeUnit.MINUTES);
 
     @VisibleForTesting
-    public static MonitoringTask instance = make(Math.max(0, CassandraRelevantProperties.SLOW_QUERY_LOG_MONITORING_REPORT_INTERVAL_IN_MS.getInt()),
-                                                 CassandraRelevantProperties.SLOW_QUERY_LOG_MONITORING_MAX_OPERATIONS.getInt());
+    public static MonitoringTask instance = make(Math.max(0, CassandraRelevantProperties.MONITORING_REPORT_INTERVAL_MS.getInt()),
+                                                 CassandraRelevantProperties.MONITORING_MAX_OPERATIONS.getInt());
 
     private final ScheduledFuture<?> reportingTask;
     private final OperationsQueue failedOperationsQueue;
@@ -318,13 +318,17 @@ protected abstract static class Operation
          * this is set lazily as it takes time to build the query CQL */
         private String name;
 
+        /** Any specific execution info of the slowest operation among the aggregated operations. */
+        protected Monitorable.ExecutionInfo slowestOperationExecutionInfo;
+
         Operation(Monitorable operation, long nowNanos)
         {
             this.operation = operation;
             numTimesReported = 1;
             totalTimeNanos = nowNanos - operation.creationTimeNanos();
             minTime = totalTimeNanos;
             maxTime = totalTimeNanos;
+            slowestOperationExecutionInfo = operation.executionInfo();
         }
 
         public String name()
@@ -334,17 +338,24 @@ public String name()
             return name;
         }
 
-        void add(Operation operation)
+        private void add(Operation operation)
         {
             numTimesReported++;
             totalTimeNanos += operation.totalTimeNanos;
+
+            if (operation.maxTime > maxTime)
+                slowestOperationExecutionInfo = operation.executionInfo();
+
             maxTime = Math.max(maxTime, operation.maxTime);
             minTime = Math.min(minTime, operation.minTime);
         }
 
         public abstract String getLogMessage();
 
-        protected abstract Monitorable.ExecutionInfo executionInfo();
+        protected Monitorable.ExecutionInfo executionInfo()
+        {
+            return slowestOperationExecutionInfo;
+        }
     }
 
     /**
@@ -360,26 +371,22 @@ private final static class FailedOperation extends Operation
         public String getLogMessage()
         {
             if (numTimesReported == 1)
-                return String.format("<%s>, total time %d msec, timeout %d %s",
+                return String.format("<%s>, total time %d msec, timeout %d %s%s",
                                      name(),
                                      NANOSECONDS.toMillis(totalTimeNanos),
                                      NANOSECONDS.toMillis(operation.timeoutNanos()),
-                                     operation.isCrossNode() ? "msec/cross-node" : "msec");
+                                     operation.isCrossNode() ? "msec/cross-node" : "msec",
+                                     slowestOperationExecutionInfo.toLogString(true));
             else
-                return String.format("<%s> timed out %d times, avg/min/max %d/%d/%d msec, timeout %d %s",
+                return String.format("<%s> timed out %d times, avg/min/max %d/%d/%d msec, timeout %d %s%s",
                                      name(),
                                      numTimesReported,
                                      NANOSECONDS.toMillis(totalTimeNanos / numTimesReported),
                                      NANOSECONDS.toMillis(minTime),
                                      NANOSECONDS.toMillis(maxTime),
                                      NANOSECONDS.toMillis(operation.timeoutNanos()),
-                                     operation.isCrossNode() ? "msec/cross-node" : "msec");
-        }
-
-        @Override
-        protected Monitorable.ExecutionInfo executionInfo()
-        {
-            return Monitorable.ExecutionInfo.EMPTY;
+                                     operation.isCrossNode() ? "msec/cross-node" : "msec",
+                                     slowestOperationExecutionInfo.toLogString(false));
         }
     }
 
@@ -389,14 +396,10 @@ protected Monitorable.ExecutionInfo executionInfo()
     @VisibleForTesting
     public final static class SlowOperation extends Operation
     {
-        /** Any specific execution info of the slowest operation among the aggregated operations. */
-        private Monitorable.ExecutionInfo slowestOperationExecutionInfo;
-
         @VisibleForTesting
         public SlowOperation(Monitorable operation, long slowAtNanos)
         {
             super(operation, slowAtNanos);
-            slowestOperationExecutionInfo = operation.executionInfo();
         }
 
         public String getLogMessage()
@@ -419,20 +422,5 @@ public String getLogMessage()
                                      operation.isCrossNode() ? "msec/cross-node" : "msec",
                                      slowestOperationExecutionInfo.toLogString(false));
         }
-
-        @Override
-        protected Monitorable.ExecutionInfo executionInfo()
-        {
-            return slowestOperationExecutionInfo;
-        }
-
-        @Override
-        void add(Operation operation)
-        {
-            if (operation.maxTime > maxTime)
-                slowestOperationExecutionInfo = operation.executionInfo();
-
-            super.add(operation);
-        }
     }
 }

src/java/org/apache/cassandra/index/sai/plan/QueryMonitorableExecutionInfo.java

@@ -52,7 +52,7 @@ private QueryMonitorableExecutionInfo(QueryContext.Snapshot metrics, String plan
      */
     public static Supplier<Monitorable.ExecutionInfo> supplier(QueryContext context, Plan plan)
     {
-        if (!CassandraRelevantProperties.SAI_SLOW_QUERY_LOG_EXECUTION_INFO_ENABLED.getBoolean())
+        if (!CassandraRelevantProperties.SAI_MONITORING_EXECUTION_INFO_ENABLED.getBoolean())
             return Monitorable.ExecutionInfo.EMPTY_SUPPLIER;
 
         String planAsString = toLogString(plan);