Merge pull request #10605 from SteveCEvans/late_tasks

Display late execution stats in tasks command

src/main/cli/cli.c

@@ -4839,7 +4839,11 @@ static void cliTasks(const char *cmdName, char *cmdline)
 
 #ifndef MINIMAL_CLI
     if (systemConfig()->task_statistics) {
+#if defined(USE_LATE_TASK_STATISTICS)
+        cliPrintLine("Task list             rate/hz  max/us  avg/us maxload avgload  total/ms   late    run reqd/us");
+#else
         cliPrintLine("Task list             rate/hz  max/us  avg/us maxload avgload  total/ms");
+#endif
     } else {
         cliPrintLine("Task list");
     }
@@ -4857,9 +4861,18 @@ static void cliTasks(const char *cmdName, char *cmdline)
                 averageLoadSum += averageLoad;
             }
             if (systemConfig()->task_statistics) {
+#if defined(USE_LATE_TASK_STATISTICS)
+                cliPrintLinef("%6d %7d %7d %4d.%1d%% %4d.%1d%% %9d %6d %6d %7d",
+                        taskFrequency, taskInfo.maxExecutionTimeUs, taskInfo.averageExecutionTimeUs,
+                        maxLoad/10, maxLoad%10, averageLoad/10, averageLoad%10,
+                        taskInfo.totalExecutionTimeUs / 1000,
+                        taskInfo.lateCount, taskInfo.runCount, taskInfo.execTime);
+#else
                 cliPrintLinef("%6d %7d %7d %4d.%1d%% %4d.%1d%% %9d",
                         taskFrequency, taskInfo.maxExecutionTimeUs, taskInfo.averageExecutionTimeUs,
-                        maxLoad/10, maxLoad%10, averageLoad/10, averageLoad%10, taskInfo.totalExecutionTimeUs / 1000);
+                        maxLoad/10, maxLoad%10, averageLoad/10, averageLoad%10,
+                        taskInfo.totalExecutionTimeUs / 1000);
+#endif
             } else {
                 cliPrintLinef("%6d", taskFrequency);
             }

src/main/scheduler/scheduler.c

@@ -174,6 +174,11 @@ void getTaskInfo(taskId_e taskId, taskInfo_t * taskInfo)
     taskInfo->averageDeltaTimeUs = getTask(taskId)->movingSumDeltaTimeUs / TASK_STATS_MOVING_SUM_COUNT;
     taskInfo->latestDeltaTimeUs = getTask(taskId)->taskLatestDeltaTimeUs;
     taskInfo->movingAverageCycleTimeUs = getTask(taskId)->movingAverageCycleTimeUs;
+#if defined(USE_LATE_TASK_STATISTICS)
+    taskInfo->lateCount = getTask(taskId)->lateCount;
+    taskInfo->runCount = getTask(taskId)->runCount;
+    taskInfo->execTime = getTask(taskId)->execTime;
+#endif
 #endif
 }
 
@@ -247,7 +252,12 @@ void schedulerResetTaskMaxExecutionTime(taskId_e taskId)
     if (taskId == TASK_SELF) {
         currentTask->maxExecutionTimeUs = 0;
     } else if (taskId < TASK_COUNT) {
-        getTask(taskId)->maxExecutionTimeUs = 0;
+        task_t *task = getTask(taskId);
+        task->maxExecutionTimeUs = 0;
+#if defined(USE_LATE_TASK_STATISTICS)
+        task->lateCount = 0;
+        task->runCount = 0;
+#endif
     }
 #else
     UNUSED(taskId);
@@ -310,6 +320,9 @@ FAST_CODE timeUs_t schedulerExecuteTask(task_t *selectedTask, timeUs_t currentTi
             }
             selectedTask->totalExecutionTimeUs += taskExecutionTimeUs;   // time consumed by scheduler + task
             selectedTask->movingAverageCycleTimeUs += 0.05f * (period - selectedTask->movingAverageCycleTimeUs);
+#if defined(USE_LATE_TASK_STATISTICS)
+            selectedTask->runCount++;
+#endif
         } else
 #endif
         {
@@ -335,6 +348,9 @@ static void readSchedulerLocals(task_t *selectedTask, uint8_t selectedTaskDynami
 
 FAST_CODE void scheduler(void)
 {
+#if defined(USE_LATE_TASK_STATISTICS)
+    static task_t *lastTask;
+#endif
     // Cache currentTime
     const timeUs_t schedulerStartTimeUs = micros();
     timeUs_t currentTimeUs = schedulerStartTimeUs;
@@ -350,7 +366,7 @@ FAST_CODE void scheduler(void)
         task_t *gyroTask = getTask(TASK_GYRO);
         const timeUs_t gyroExecuteTimeUs = getPeriodCalculationBasis(gyroTask) + gyroTask->desiredPeriodUs;
         gyroTaskDelayUs = cmpTimeUs(gyroExecuteTimeUs, currentTimeUs);  // time until the next expected gyro sample
-        if (cmpTimeUs(currentTimeUs, gyroExecuteTimeUs) >= 0) {
+        if (gyroTaskDelayUs <= 0) {
             taskExecutionTimeUs = schedulerExecuteTask(gyroTask, currentTimeUs);
             if (gyroFilterReady()) {
                 taskExecutionTimeUs += schedulerExecuteTask(getTask(TASK_FILTER), currentTimeUs);
@@ -360,6 +376,16 @@ FAST_CODE void scheduler(void)
             }
             currentTimeUs = micros();
             realtimeTaskRan = true;
+
+#if defined(USE_LATE_TASK_STATISTICS)
+           // Late, so make a note of the offending task
+            if (gyroTaskDelayUs < -1) {
+                if (lastTask) {
+                    lastTask->lateCount++;
+                }
+            }
+            lastTask = NULL;
+#endif
         }
     }
 
@@ -426,6 +452,9 @@ FAST_CODE void scheduler(void)
 #if defined(USE_TASK_STATISTICS)
             if (calculateTaskStatistics) {
                 taskRequiredTimeUs = selectedTask->movingSumExecutionTimeUs / TASK_STATS_MOVING_SUM_COUNT + TASK_AVERAGE_EXECUTE_PADDING_US;
+#if defined(USE_LATE_TASK_STATISTICS)
+                selectedTask->execTime = taskRequiredTimeUs;
+#endif
             }
 #endif
             // Add in the time spent so far in check functions and the scheduler logic
@@ -435,6 +464,10 @@ FAST_CODE void scheduler(void)
             } else {
                 selectedTask = NULL;
             }
+
+#if defined(USE_LATE_TASK_STATISTICS)
+            lastTask = selectedTask;
+#endif
         }
     }
 

src/main/scheduler/scheduler.h

@@ -64,6 +64,11 @@ typedef struct {
     timeUs_t     averageExecutionTimeUs;
     timeUs_t     averageDeltaTimeUs;
     float        movingAverageCycleTimeUs;
+#if defined(USE_LATE_TASK_STATISTICS)
+    uint32_t     runCount;
+    uint32_t     lateCount;
+    timeUs_t     execTime;
+#endif
 } taskInfo_t;
 
 typedef enum {
@@ -179,6 +184,11 @@ typedef struct {
     timeUs_t movingSumDeltaTimeUs;  // moving sum over 32 samples
     timeUs_t maxExecutionTimeUs;
     timeUs_t totalExecutionTimeUs;    // total time consumed by task since boot
+#if defined(USE_LATE_TASK_STATISTICS)
+    uint32_t runCount;
+    uint32_t lateCount;
+    timeUs_t execTime;
+#endif
 #endif
 } task_t;
 

src/main/target/common_pre.h

@@ -124,6 +124,7 @@
 #define USE_RTC_TIME
 #define USE_PERSISTENT_MSC_RTC
 #define USE_DSHOT_CACHE_MGMT
+#define USE_LATE_TASK_STATISTICS
 #endif
 
 #ifdef STM32G4