Display late execution stats in tasks command

This commit is contained in:
Steve Evans 2021-03-07 20:46:25 +00:00
parent bc4372588b
commit bb119e95c5
4 changed files with 61 additions and 4 deletions

View File

@ -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);
}

View File

@ -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
}
}

View File

@ -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;

View File

@ -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