Getting useful task stats from FreeRTOS

micron
Posts: 8
Joined: Thu Nov 09, 2023 7:09 pm

Getting useful task stats from FreeRTOS

Postby micron » Sun Nov 12, 2023 6:55 pm

FreeRTOS provides the function vTaskGetRunTimeStats(char * pBuffer).

On my ESP32-S3 it prints a report that looks like...

Code: Select all

cli_proc       13831<1%
cli@tty0       243301<1%
IDLE           5646366198%
IDLE           5596399097%
Tmr Svc        10289<1%
ipc1           9586061%
blinky         12124<1%
ipc0           9439331%
esp_timer      24<1%
This is only after a few seconds runtime; the numbers grow to incomprehensible very quickly. This may be useful to some, but I would like to know about how close the stack has come to its limit for each task, and as an added metric for dual core processors, how much time each task runs on each core.

I came up with a technique that works, but I'm not 100% happy with it. My un-breakable rule is to never touch any file outside my own directory, especially within an SDK/IDF. So...

I added the following lines to my MakeLists.txt file

Code: Select all

add_compile_definitions(traceTASK_SWITCHED_OUT=taskExit;traceTASK_SWITCHED_IN=taskEnter)
add_compile_options($<$<COMPILE_LANGUAGE:C>:-Wno-implicit-function-declaration>)
Then I coded the two functions

Code: Select all

typedef struct
{
	TaskHandle_t			hTask;
	uint64_t			taskCoreRunTime[configNUM_CORES];
	int64_t				enterTime;
}TASK_RUN_COUNTER;


TASK_RUN_COUNTER taskRunCounters[MAX_FREERTOS_TASKS];	// run counters for all tasks


///////////////////////
// Hook task scheduler
///////////////////////

void IRAM_ATTR taskEnter()
{
	TaskHandle_t	_hTask = xTaskGetCurrentTaskHandle();
	uint8_t			_index;
	int64_t 		_now = esp_timer_get_time();
	
	for (_index = 0; _index < MAX_FREERTOS_TASKS; _index++ )
	{
		if ( ( taskRunCounters[_index].hTask == _hTask ) || ( taskRunCounters[_index].hTask == NULL ) )
		{
			taskRunCounters[_index].hTask = _hTask;
			taskRunCounters[_index].enterTime = _now;
			break;
		}
	}
}

void IRAM_ATTR taskExit()
{
	TaskHandle_t	_hTask = xTaskGetCurrentTaskHandle();
	uint8_t			_index;
	int64_t 		_now = esp_timer_get_time();
	
	for (_index = 0; _index < MAX_FREERTOS_TASKS; _index++ )
	{
		if ( taskRunCounters[_index].hTask == _hTask )
		{
			taskRunCounters[_index].taskCoreRunTime[xPortGetCoreID()] += ( _now - taskRunCounters[_index].enterTime );
			break;
		}
	}
}
It's ugly, in my opinion, that in the hook functions, I have to add a new TASK_RUN_COUNTER structure, and then scan it for the matching task handle. I wanted to use the uxTCBNumber as a direct index into the array, but can't find a function that returns it.

So then along with the metrics provided by the FreeRTOS function uxTaskGetSystemState(), I am able to produce an output that looks like ..

Code: Select all

  Runtime:     0::00:10:22.513
  9 Tasks...
  Name                   State      Prio     Stack base,high    Run Core 0         Run Core 1        
  ----                   -----      ----     ---------------    ----------         ----------        
  ipc1                   suspended  24(24)   0x3FCA2E18,456      0::00:00:00.000    0::00:00:00.009
  ipc0                   suspended  24(24)   0x3FCA26B0,448      0::00:00:00.000    0::00:00:00.000
  esp_timer              suspended  22(22)   0x3FCA3580,3056     0::00:00:00.000    0::00:00:00.000
  cli_proc               running    10(10)   0x3FCA9A50,2320     0::00:00:00.296    0::00:00:00.000
  cli@tty0               ready      07(07)   0x3FCA8620,2000     0::00:00:02.340    0::00:00:00.004
  blinky                 blocked    04(04)   0x3FCAAD9C,2884     0::00:00:00.111    0::00:00:00.000
  Tmr Svc                blocked    01(01)   0x3FCA69E0,784      0::00:00:00.081    0::00:00:00.000
  IDLE                   ready      00(00)   0x3FCA6138,888      0::00:00:00.000    0::00:10:21.621
  IDLE                   ready      00(00)   0x3FCA5890,624      0::00:10:18.329    0::00:00:00.000
Now it can run for many days and still produce readable output.

But... my question is... has anyone done something similar, and if so, cleaner, neater?

MicroController
Posts: 1708
Joined: Mon Oct 17, 2022 7:38 pm
Location: Europe, Germany

Re: Getting useful task stats from FreeRTOS

Postby MicroController » Mon Nov 13, 2023 11:15 pm

has anyone done something similar, and if so, cleaner, neater?
Yes, but no, and no :)
It's ugly, in my opinion, that in the hook functions, I have to add a new TASK_RUN_COUNTER structure, and then scan it for the matching task handle. I wanted to use the uxTCBNumber as a direct index into the array, but can't find a function that returns it.
IIRC, I also added traceTASK_CREATE and traceTASK_DELETE hooks to add or remove entries from my private task list so I won't have to do it during the context switches.
OTOH, iterating over an array with some <= 32 entries is pretty fast.
For some related reason (can't remember) I also copied the tskTCB/TCB_t struct's typedef from tasks.c into my project which then allowed me to access all the fine 'internal' fields which FreeRTOS doesn't care to provide read access functions for, including ulRunTimeCounter. Talking about 'ugly'... ;)

I did not use esp_timer_get_time() because it can be really 'slow', like 1-2us. esp_cpu_get_cycle_count() executes in a single CPU clock cycle.

micron
Posts: 8
Joined: Thu Nov 09, 2023 7:09 pm

Re: Getting useful task stats from FreeRTOS

Postby micron » Tue Nov 14, 2023 6:28 pm

I did not use esp_timer_get_time() because it can be really 'slow', like 1-2us. esp_cpu_get_cycle_count() executes in a single CPU clock cycle.
Thank you for your insight. I took a look at esp_cpu_get_cycle_count(); it looks like it returns a uint32, and I'm not even sure of the units. In any case, it's likely to wrap very quickly; so, I'm maybe better off using esp_timer_get_time() rather than try to handle the wrap with code? I don't think I'm at the point yet of being overly concerned with adding a uS or two during task switching.

MicroController
Posts: 1708
Joined: Mon Oct 17, 2022 7:38 pm
Location: Europe, Germany

Re: Getting useful task stats from FreeRTOS

Postby MicroController » Wed Nov 15, 2023 2:52 pm

Yes, esp_cpu_get_cycle_count() will wrap around every ~4bn CPU cycles, i.e. about every 17.9 seconds @ 240MHz.
Of course, if any task would run for 18 seconds uninterrupted (which the IDLE task might), this could cause a wrong reading. For me this wasn't a problem because I was taking 'snapshots' every 1-2 seconds to update "current CPU load" at that rate, so none of my counters would have to count more than 2 seconds worth of CPU cylces.

Who is online

Users browsing this forum: ignisuti and 127 guests