ESP32 Forum

ESP32 Official Forum
http://esp32.io/

uxTaskGetSystemState() working BUT runtime stats vary wildly

http://esp32.io/viewtopic.php?f=2&t=1532

Page 1 of 1

uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Sun Mar 26, 2017 8:29 pm
by ammaree
I have spend quite some time trying to make the uxTaskGetSystemState() function work and producing sensible results but have reached a brick wall. First some background.

In portmacro.h the ESP-IDF seems to hardwire the FreeRTOS macro to the xthal_get_ccount() function. The problem with this approach is that with the runtime stats counter being a 32bit value it wraps within <18secs making the functionality over little value.

In order to overcome this restriction I changed portmacro.h as follows:

Code: Select all

void		halTIMER_InitRtosStats(void) ;
#define portCONFIGURE_TIMER_FOR_RUN_TIME_STATS()	halTIMER_InitRtosStats()
uint32_t	halTIMER_ReadRtosStats(void) ;
#define portGET_RUN_TIME_COUNTER_VALUE()    		halTIMER_ReadRtosStats()
//#define portGET_RUN_TIME_COUNTER_VALUE()  xthal_get_ccount()
In my timer support module I then have the following:

Code: Select all

#define configSTATS_CLOCK_DIVISOR value between 10000

static	uint32_t	LastClock, RunTime, DifClock ;

uint32_t	halTIMER_ReadRtosStats(void) {
	DifClock	= xthal_get_ccount() - LastClock ;
	RunTime		+= (DifClock / configSTATS_CLOCK_DIVISOR) ;
	LastClock	= xthal_get_ccount() ;
	return RunTime ;
}

void	halTIMER_InitRtosStats(void) {
	LastClock	= xthal_get_ccount() ;					// setup initial value for task statistics
	RunTime		= 0 ;
}
By changing the configSTATS_CLOCK_DIVISOR value I can change the resolution to see the different results.

The function used to read and display the task info is exactly the same as that used in a Cortex M4/CC3200LP based platform with the only additional (conditional compilation) code being that to read and display the MCU affinity information.

I expected the results to be reasonably consistent but with the total% to be around 200% as a result of the dual MCU's but alas this is not the case, it is completely random, as you can see below.

Any suggestions?

Also, if you can please help with some background information on each of the tasks, just to understand what they do, it would be much appreciated.

Thanks

Code: Select all

 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 0.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.00|   2780193| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 0.01|  87944804| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 1.00|2312935194| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 1.00|  83752026| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.00|   1084760| 0 | ppT
 |10 | 21/21 | B | 3,984 | 0.00|   1781634| X | pmT
 |11 | 22/22 | B |11,920 | 0.00|     15959| X | rtT
 |12 |  5/ 5 | P | 6,480 | 0.00|   1781655| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781650| 1 | TskSntp
Total% =  2.01 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:10:15 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 |43.06| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 4.31|   2788172| 0 | main
 | 4 |  0/ 0 | P | 3,456 |59.53| 168720084| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 |17.56|3189820339| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 |12.00| 179959340| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.01|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 3.21|   2287963| 0 | ppT
 |10 | 21/21 | B | 3,984 |50.52|  33850775| X | pmT
 |11 | 22/22 | B |11,920 | 0.23|    159347| X | rtT
 |12 |  5/ 5 | B | 6,480 | 2.09|   1781696| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 2.09|   1781668| 1 | TskSntp
Total% = 194.61 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:10:27 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 2.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.01|   2796141| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 3.02| 249360130| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 0.01|4039981436| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 2.01| 244097701| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.03|   3355740| 0 | ppT
 |10 | 21/21 | B | 3,984 | 1.03|  58793480| X | pmT
 |11 | 22/22 | B |11,920 | 0.02|    278837| X | rtT
 |12 |  5/ 5 | B | 6,480 | 0.00|   1781729| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781685| 1 | TskSntp
Total% =  8.13 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:10:39 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 1.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.01|   2804108| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 1.00| 331781784| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 1.01| 595175179| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 0.01| 320715292| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.00|   4471308| 0 | ppT
 |10 | 21/21 | B | 3,984 | 1.00|  85517797| X | pmT
 |11 | 22/22 | B |11,920 | 0.01|    398328| X | rtT
 |12 |  5/ 5 | B | 6,480 | 0.00|   1781765| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781702| 1 | TskSntp
Total% =  4.04 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:10:51 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 0.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.00|   2812074| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 0.00| 412541148| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 0.00|1470278722| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 1.00| 420493774| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.00|   5682486| 0 | ppT
 |10 | 21/21 | B | 3,984 | 1.01| 119368544| X | pmT
 |11 | 22/22 | B |11,920 | 0.00|    549683| X | rtT
 |12 |  5/ 5 | B | 6,480 | 0.00|   1781803| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781719| 1 | TskSntp
Total% =  2.01 - Heap: 236,236 / 238,184 / 285,968
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 |192.29| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 |18.61|   2820040| 0 | main
 | 4 |  0/ 0 | P | 3,456 |138.21| 493244842| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 |90.09|2332910974| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 |283.54| 514919470| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.05|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 |45.09|   6885699| 0 | ppT
 |10 | 21/21 | B | 3,984 |103.00| 144311264| X | pmT
 |11 | 22/22 | B |11,920 | 4.54|    661207| X | rtT
 |12 |  5/ 5 | B | 6,480 |11.42|   1781841| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 |11.42|   1781719| 1 | TskSntp
Total% = 898.26 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:11:03 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 2.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.02|   2828010| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 1.01| 573972334| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 2.03|3204451256| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 1.00| 614697969| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.03|   8104846| 0 | ppT
 |10 | 21/21 | B | 3,984 | 0.03| 178162017| X | pmT
 |11 | 22/22 | B |11,920 | 0.03|    812561| X | rtT
 |12 |  5/ 5 | B | 6,480 | 0.00|   1781880| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781736| 1 | TskSntp
Total% =  6.15 - Heap: 236,236 / 238,184 / 285,968
CPU=1 Date/time in SA is Sun Mar 26 23:11:15 2017
 |F# | Pc/Pb | S | LoStk |%Util|TimerTicks|MCU|-Name-
 | 1 | 24/24 | B | 4,176 | 0.00|         1| 0 | ipc0
 | 2 | 24/24 | B | 3,616 | 1.00| 758965697| 1 | ipc1
 | 3 |  1/ 1 | R | 8,992 | 0.01|   2835977| 0 | main
 | 4 |  0/ 0 | P | 3,456 | 0.00| 654588539| 0 | IDLE
 | 5 |  0/ 0 | P | 3,456 | 0.01|4047485870| 1 | IDLE
 | 6 |  1/ 1 | B | 7,024 | 0.00|         3| 0 | Tmr Svc
 | 7 | 18/18 | B | 4,016 | 1.01| 684181147| X | tiT
 | 8 | 20/20 | B | 1,568 | 0.00|      8049| 0 | eventTask
 | 9 | 23/23 | B | 5,808 | 0.00|   9188547| 0 | ppT
 |10 | 21/21 | B | 3,984 | 1.01| 203104721| X | pmT
 |11 | 22/22 | B |11,920 | 0.00|    924085| X | rtT
 |12 |  5/ 5 | B | 6,480 | 0.00|   1781912| 1 | TskBlink
 |13 |  5/ 5 | B | 2,224 | 0.00|   1781753| 1 | TskSntp

Re: uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Mon Mar 27, 2017 1:32 am
by ESP_Sprite
I'm willing to look into this: something like top has always been on the list of things to implement. Are you okay with sharing your code in a way where it eventually ends up in esp-idf? Do you have a link to your patches or something?

Re: uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Mon Mar 27, 2017 7:56 pm
by ammaree
I am happy to share the code already posted (2 minute functions) as well as the single function required to create the output.

I am comfortable that it gets incorporated into esp-idf provided it does not prohibit my options to continue developing it further, should I so desire.

Would you like me to post it here or send to you via PM to be incorporated.

Re: uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Tue Mar 28, 2017 2:58 am
by ESP_Sprite
Feel free to mail it to me: jeroen at espressif period com

Re: uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Tue Mar 28, 2017 7:29 am
by ammaree
Will post you the code but just an update.

Part of the logic was faulty since the Util% was calculated in a way that caused regular wrapping on a uint32_t. Changing the sequence of calculation removed some of the wrap.

As is the Util% now often calculates to what seems an accurate 99.40% to 99.96%. The regularity of wildly incorrect readings are now directly proportional to the period/interval used in the stats counter. With a 100uS interval the readings are significantly more consistent than with a 10uS interval possibly indicating a further direct link to the counter wrapping.

I will have a further look at this to see if I can find the cause before sending the code to you.

Re: uxTaskGetSystemState() working BUT runtime stats vary wildly

Posted: Thu Aug 03, 2017 1:39 am
by jkhax0r
From what I could tell, the xthal_get_ccount() function returns a different value for different cores. So I wrote functions equivalent to yours, but CPU ID aware.

Code: Select all

extern uint64_t get_run_time_counter_value(void);
extern void init_run_time_counter(void);

#define portGET_RUN_TIME_COUNTER_VALUE() get_run_time_counter_value()
#define portCONFIGURE_TIMER_FOR_RUN_TIME_STATS() init_run_time_counter()

Code: Select all

uint32_t last_clock_time[portNUM_PROCESSORS];
uint32_t total_clock_time[portNUM_PROCESSORS] = {0};
uint8_t loaded_clock_time[portNUM_PROCESSORS] = {0};
void init_run_time_counter(void)
{
    int id = xPortGetCoreID();
    last_clock_time[id] = xthal_get_ccount();
    loaded_clock_time[id] = 1;
}

uint32_t get_run_time_counter_value(void)
{
    int id = xPortGetCoreID();
    uint32_t now = xthal_get_ccount();

    if (!loaded_clock_time[id]) {
        last_clock_time[id] = now;
        loaded_clock_time[id] = 1;
        return total_clock_time[id];
    }

    int32_t dt = (int32_t)(now - last_clock_time[id]);
    last_clock_time[id] = now;

#if defined ( CONFIG_ESP32_DEFAULT_CPU_FREQ_240 )
    total_clock_time[id] += dt / 240;
#elif defined ( CONFIG_ESP32_DEFAULT_CPU_FREQ_160 )
    total_clock_time[id] += dt / 160;
#else
    total_clock_time[id] += dt / 80;
#endif

    //ets_printf("id=%d, %d\n", id, now);

    return total_clock_time[id];
}
Then there are two globals in tasks.c that need to be processor specific - along with all the references.

Code: Select all

	PRIVILEGED_DATA static uint32_t ulTaskSwitchedInTime[portNUM_PROCESSORS] = {0UL};	/*< Holds the value of a timer/counter the last time a task was switched in. */
	PRIVILEGED_DATA static uint32_t ulTotalRunTime[portNUM_PROCESSORS] = {0UL};		/*< Holds the total amount of execution time as defined by the run time counter clock. */
And finally theres a reference to *pulTotalRunTime that I changed to just accumulate all task run times as follows:

Code: Select all

if( pulTotalRunTime != NULL )
            {
                uint32_t tot = 0;
                for (int i = 0; i < uxCurrentNumberOfTasks; ++i) {
                    tot += pxTaskStatusArray[i].ulRunTimeCounter;
                }
                *pulTotalRunTime = tot;
            }
Seems to work well. Would be a whole lot nicer if the two clocks could somehow be synced, but I'm not sure how. I just went with a divider for 1us timer (so a bit over an hour before a wrap will occur). With all these hacks it would be just as easy to change to uint64_t.... actually I just did and it should be working.
All times are UTC
Page 1 of 1
Powered by phpBB® Forum Software © phpBB Limited
https://www.phpbb.com/