From bb119e95c54f81238cfd53ac5fec8ea705d14ed0 Mon Sep 17 00:00:00 2001 From: Steve Evans Date: Sun, 7 Mar 2021 20:46:25 +0000 Subject: [PATCH] Display late execution stats in tasks command --- src/main/cli/cli.c | 15 +++++++++++++- src/main/scheduler/scheduler.c | 37 ++++++++++++++++++++++++++++++++-- src/main/scheduler/scheduler.h | 10 +++++++++ src/main/target/common_pre.h | 3 ++- 4 files changed, 61 insertions(+), 4 deletions(-) diff --git a/src/main/cli/cli.c b/src/main/cli/cli.c index 81026071ad..4f9b73f944 100644 --- a/src/main/cli/cli.c +++ b/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); } diff --git a/src/main/scheduler/scheduler.c b/src/main/scheduler/scheduler.c index 62e09cbbdf..36406fe7dc 100644 --- a/src/main/scheduler/scheduler.c +++ b/src/main/scheduler/scheduler.c @@ -173,6 +173,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 } @@ -240,7 +245,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); @@ -300,6 +310,9 @@ FAST_CODE timeUs_t schedulerExecuteTask(task_t *selectedTask, timeUs_t currentTi selectedTask->totalExecutionTimeUs += taskExecutionTimeUs; // time consumed by scheduler + task selectedTask->maxExecutionTimeUs = MAX(selectedTask->maxExecutionTimeUs, taskExecutionTimeUs); selectedTask->movingAverageCycleTimeUs += 0.05f * (period - selectedTask->movingAverageCycleTimeUs); +#if defined(USE_LATE_TASK_STATISTICS) + selectedTask->runCount++; +#endif } else #endif { @@ -325,6 +338,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; @@ -340,7 +356,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); @@ -350,6 +366,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 } } @@ -416,6 +442,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 @@ -425,6 +454,10 @@ FAST_CODE void scheduler(void) } else { selectedTask = NULL; } + +#if defined(USE_LATE_TASK_STATISTICS) + lastTask = selectedTask; +#endif } } diff --git a/src/main/scheduler/scheduler.h b/src/main/scheduler/scheduler.h index 3324444802..6c79886202 100644 --- a/src/main/scheduler/scheduler.h +++ b/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; diff --git a/src/main/target/common_pre.h b/src/main/target/common_pre.h index e0dacb18ed..dd7109da5e 100644 --- a/src/main/target/common_pre.h +++ b/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 @@ -184,7 +185,7 @@ #endif #ifdef USE_FAST_DATA -#define FAST_DATA_ZERO_INIT __attribute__ ((section(".fastram_bss"), aligned(4))) +#define FAST_DATA_ZERO_INIT __attribute__ ((section(".fastram_bss"), aligned(4))) #define FAST_DATA __attribute__ ((section(".fastram_data"), aligned(4))) #else #define FAST_DATA_ZERO_INIT