esp_timer consumes 50% of CPU time, please help

[bs-eng]

Hello all!

I ran into a speed issue with my code. So I gathered the info on all tasks and noticed that the task esp_timer is consuming about half of the available CPU time. See stats here:

Code: Select all

W (587604) AUDIOBOX:  #            task name  core free stack   run time      in %%
W (587614) AUDIOBOX:  0            AudioTask     1      13856     373664         <1%
W (587614) AUDIOBOX:  1                 main     0       2056     463896         <1%
W (587614) AUDIOBOX:  2                 IDLE     1        936  585918953         99%
W (587634) AUDIOBOX:  3                 IDLE     0        928  274725393         46%
W (587634) AUDIOBOX:  4           esp_periph     0       2316    2387659         <1%
W (587634) AUDIOBOX:  5              Tmr Svc     0        160     924679         <1%
W (587634) AUDIOBOX:  6                 file     0       2176     268981         <1%
W (587634) AUDIOBOX:  7                  mp3     0       3892    2513101         <1%
W (587634) AUDIOBOX:  8               filter     0       2960    1114041         <1%
W (587634) AUDIOBOX:  9                  i2s     0       2640     599156         <1%
W (587634) AUDIOBOX: 10                 ipc0     0        952       8576         <1%
W (587644) AUDIOBOX: 11                 hciT     0       1568     504208         <1%
W (587644) AUDIOBOX: 12             BTU_TASK     0       2964     752456         <1%
W (587644) AUDIOBOX: 13             BTC_TASK     0       1508     355212         <1%
W (587644) AUDIOBOX: 14         btController     0       2016    5001571         <1%
W (587644) AUDIOBOX: 15            esp_timer     0       3324  296709377         50%
W (587644) AUDIOBOX: 16      input_key_servi     1       2472         68         <1%

My timer tick is set to 100 Hz as I need only time intervals in the range of 10ms to a few minutes.
In the timer callback all I do is put a message on a queue, which is later handled in a task, like this:

Code: Select all

err = xQueueSend( queue_toStateMachine, ( void * ) &outMsg, ( TickType_t ) 2 );

In order to monitor how often the timer puts a message on the queue, I put some log outputs on the timer event handling in the task. As normally expected they hardly ever get called and cannot explain the high CPU load of the esp_timer.

What can I do to reduce the load of esp_timer on the CPU?
What are the typical reasons for such load?

Thanks a lot!
cheers
JRA

[DrMickeyLauer]

This is tough to say without knowing your code. Perhaps a part of your code is doing too much work in a timer callback instead of scheduling another task wakeup?

[bs-eng]

Thanks for looking into it!
My timer callback do things like this:

Code: Select all

static void alarmTimerCallback( TimerHandle_t pxTimer ){
	knob_t* knob;
	Message_t outMsg;
	BaseType_t err;
	ESP_LOGE( TAG, "alarm timer callback triggered......");		//TODO debug, remove

	knob = ( knob_t* ) pvTimerGetTimerID( pxTimer );
	ESP_LOGD( TAG, "Alarm triggered..." );
	knob->AlarmState = true;
	outMsg.event = EVT_AlarmTimeOut;
	outMsg.id = knob;
	err = xQueueSend( queue_toStateMachine, ( void * ) &outMsg, ( TickType_t ) 2 );
	if ( err != pdTRUE) ESP_LOGE( TAG, "Error: Timer event could not be placed on queue.");
}

or even more simple:

Code: Select all

static void exclTimerCallback( TimerHandle_t pxTimer ){
	knob_t* knob;
	Message_t outMsg;
	TickType_t timerPeriod;
	BaseType_t err;
	
	ESP_LOGE( TAG, "knob timer callback triggered......");		//TODO debug, remove

    // the timer has reached its final value, so we set the handed over timerEvtFlag
	knob = ( knob_t* ) pvTimerGetTimerID( pxTimer );
	timerPeriod = xTimerGetPeriod( pxTimer );

	if ( queue_toStateMachine != NULL ){
		switch( timerPeriod ){
		case pdMS_TO_TICKS( MY_WAIT_TIME ):
			outMsg.event = EVT_WaitTimeout;
			break;

		case pdMS_TO_TICKS( MY_MUTE_TIME ):
			outMsg.event = EVT_MuteTimeout;
			break;

		case pdMS_TO_TICKS( MY_MENU_TIME ):
			outMsg.event = EVT_MenuTimeOut;
			break;
		}
		outMsg.id = knob;
		err = xQueueSend( queue_toStateMachine, ( void * ) &outMsg, ( TickType_t ) 2 );
		if ( err == pdTRUE) return;
	}
	ESP_LOGE( TAG, "Error: Timer event could not be placed on queue.");
}

So they are sending messages out to wake up other tasks, exactly as you describe. Unless I missed something.

[MSzymanek]

Off the top of my head these things stand out:
- If the lowest time you want the state machine to update is every 10ms, maybe vTaskDelay can be used instead of the timer? vTaskDelay(1) should technically call back every 10 ms with the default FreeRTOS tick rate. Obviously this only works if you don't send other messages into the queue.
- When debugging timing I recommend to uncomment every LOG statement, since these take a lot of memory and can take a long time to process. A good way to measure time precisely - if you have an oscilloscope - is to turn on a GPIO in the block you want to measure time of.
- You call the timer every 10ms, but your xQueueSend() call blocks for up to 20ms, assuming standard rtos tick rate. This is likely to cause timing issues, even if the queue is not full

[MicroController]

Care to share more of your code?
How do you set up the timer?
Do you have more callbacks than the two you showed?

You can also look into using FreeRTOS timers if their 10ms resolution is acceptable.

[bs-eng]

Yes, I have exactly those two callbacks in my code. They handle all timers that may be running.

To my understanding I am using already the FreeRTOS timers of the ESP-IDF framework, am I not? Yes, I am fully content with a 10ms minimum period. Usually I need only multiple of 100ms.

The code to create/restart any of those timers are these two functions:

Code: Select all

static void startAlarmTimer(knob_t* knob)
{
	TickType_t ticks = pdMS_TO_TICKS((knob->alarmTime) * 60 * 1000UL);

	if ( knob->timerAlarmHandle == NULL)
	{	//! If timer is not yet created, create a timer for this knob.
		knob->timerAlarmHandle = xTimerCreate( "t", \
				ticks, \
				pdFALSE, \
				knob, \
				alarmTimerCallback );
		//! Start the timer.
		xTimerStart( knob->timerAlarmHandle, 2 );
		ESP_LOGD( TAG, "Alarm: Started timer." );
	}
	else
	{
		// set timer period to alarm interval and start the timer
		xTimerChangePeriod( knob->timerAlarmHandle, \
				ticks, \
				2 );
	}
}

and:

Code: Select all

static void setTimer( knob_t* knob, TickType_t ticks){
	BaseType_t err;

	if ( knob->timerHandle == NULL)
	{//! If timer is not yet created, create a timer for this knob.
		knob->timerHandle = xTimerCreate( "t", ticks, pdFALSE, knob, exclusiveTimerCallback );
		//! Start the timer.
		xTimerStart( knob->timerHandle, 2 );
		ESP_LOGD( TAG, "Start timer done, new period is %lu ticks", xTimerGetPeriod( knob->timerHandle ) );
	}
	else {
		//! Else set new timer period, this starts the timer automatically
		err = xTimerChangePeriod( knob->timerHandle, ticks, 2 );
		if( err != pdPASS ) ESP_LOGE( TAG, "Could not change timer period to %lu", ticks );
		//! Make sure the timer is started from zero (should only be an issue if
		//! the timer is already running, which is an error case at this point.
		xTimerReset( knob->timerHandle, 2 );
		if( err != pdPASS ) ESP_LOGE( TAG, "Could not reset timer" );
		ESP_LOGD( TAG, "Reset timer done, new period is %lu ticks", xTimerGetPeriod( knob->timerHandle ) );
	}
}

Anything wrong in there?

[bs-eng]

Back to this task now...
To see what is happening in the timer I added the esp_timer_dump() and am surprised to find that the touch filter timer is consuming large amounts of CPU time and gets triggered at a rate of approximately 30 times per second (estimate from log timestamp and esp_timer_dump() values).
Here is an example log:

Code: Select all

W (53305) mytask:  #            task name  core free stack   run time      in %%
W (53305) mytask:  0              Tmr Svc     0        160     108205         <1%
W (53305) mytask:  1                 main     0       1864    2221066          4%
W (53305) mytask:  2                 IDLE     1        904   51912801         99%
W (53305) mytask:  3                 IDLE     0        928   13097351         25%
W (53315) mytask:  4            AudioTask     1      13868      79815         <1%
W (53315) mytask:  5           esp_periph     0       2308     313984         <1%
W (53315) mytask:  6                 file     0       2032     386011         <1%
W (53315) mytask:  7                  mp3     0       3892    5007530          9%
W (53315) mytask:  8               filter     0       2976    2650776          5%
W (53325) mytask:  9                  i2s     0       2640    1375460          2%
W (53335) mytask: 10                 ipc1     1        944      36490         <1%
W (53335) mytask: 11             BTU_TASK     0       2968     142065         <1%
W (53335) mytask: 12                 hciT     0       1580     108535         <1%
W (53335) mytask: 13             BTC_TASK     0       1516      99754         <1%
W (53335) mytask: 14         btController     0       2128    1033249          1%
W (53335) mytask: 15            esp_timer     0       3324   25465910         48%
W (53335) mytask: 16                 ipc0     0        952       8626         <1%
W (53335) mytask: 17      input_key_servi     1       2476         59         <1%
Timer stats:
Name                  Period      Alarm         Times_armed   Times_trigg   Times_skip    Cb_exec_time
touch filter timer    30000       52072646      1             1707          7             26367874
adv_fc_mon            0           0             76            76            0             19179
cmd_rsp_to            0           0             19            0             0             0
ETSTimer              0           0             0             0             0             0

I am using a LyraTv4.3 as a development platform and by now removed all electrical connections that could be potentially creating any noise.
Still the high rate of triggering.
Is the trigger rate normal?
Can I change the trigger rate somewhere in sdkconfig? Where else might I find respective settings?
I would even be happy to simply remove the touch pads completely, as I am using only the hardware buttons.

Thanks a lot!


Edit: I removed all code from the callback of periph_service_set_callback() and still observe the high Cb_exec_time.

[bs-eng]

Hi!
Meanwhile I used two plain examples from ADFv2.6 called pipeline_play_sdcard_music and pipeline_sdcard_mp3_control and added support for:

• esp_timer_dump()
• uxTaskGetSystemState()

in order to collect system stats.

In pipeline_play_sdcard_music the touch peripheral is not used, not even initialized as far as I can see. There is no timer running according to esp_timer_dump().

Code: Select all

W (17969) PLAY_SDCARD_MUSIC:  #            task name  core free stack   run time      in %%
W (17979) PLAY_SDCARD_MUSIC:  0                 main     0       1588    1250767          7%
W (17979) PLAY_SDCARD_MUSIC:  1                 IDLE     1       1036   16569970         99%
W (17989) PLAY_SDCARD_MUSIC:  2                 IDLE     0        912   11278011         67%
W (17999) PLAY_SDCARD_MUSIC:  3              Tmr Svc     0       1268       1283         <1%
W (18009) PLAY_SDCARD_MUSIC:  4           esp_periph     0       2424      75025         <1%
W (18019) PLAY_SDCARD_MUSIC:  5                 ipc0     0        480      55361         <1%
W (18029) PLAY_SDCARD_MUSIC:  6                 file     0       1944     138574         <1%
W (18039) PLAY_SDCARD_MUSIC:  7                  i2s     0       2572     358397          2%
W (18049) PLAY_SDCARD_MUSIC:  8            esp_timer     0       3576         29         <1%
W (18059) PLAY_SDCARD_MUSIC:  9                 ipc1     1        488      60206         <1%
W (18069) PLAY_SDCARD_MUSIC: 10                  dec     0       3884    3477749         20%
Timer stats:
Name                  Period      Alarm         Times_armed   Times_trigg   Times_skip    Cb_exec_time

In pipeline_sdcard_mp3_control however the CPU load is recorded as roughly 50% for esp_timer. The touch filter timer is running according to esp_timer_dump().

Code: Select all

W (79193) TOUCHTIMER:  #            task name  core free stack   run time      in %%
W (79213) TOUCHTIMER:  0                 main     0       1404   19191007         24%
W (79213) TOUCHTIMER:  1                 IDLE     1        916   77714232         99%
W (79223) TOUCHTIMER:  2                 IDLE     0        920   12753128         16%
W (79243) TOUCHTIMER:  3           esp_periph     0       2312     362137         <1%
W (79243) TOUCHTIMER:  4              Tmr Svc     0       1116     125350         <1%
W (79253) TOUCHTIMER:  5               filter     0       2988    1143378          1%
W (79273) TOUCHTIMER:  6                  i2s     0       2572     546368         <1%
W (79273) TOUCHTIMER:  7      input_key_servi     1       1168      15744         <1%
W (79283) TOUCHTIMER:  8                 ipc1     1        488      60194         <1%
W (79303) TOUCHTIMER:  9                 file     0       2012     128207         <1%
W (79303) TOUCHTIMER: 10            esp_timer     0       3424   40960276         52%
W (79313) TOUCHTIMER: 11                  mp3     0       3876    2532796          3%
W (79333) TOUCHTIMER: 12                 ipc0     0        480      55301         <1%
Timer stats:
Name                  Period      Alarm         Times_armed   Times_trigg   Times_skip    Cb_exec_time
touch filter timer    30000       77932000      1             2593          0             41182095

So my deduction is that the touch peripheral is using up the CPU load by using massive amounts of time in its callback function.

How can this be prevented?
Is there a way to configure the touch peripheral differently?

my setup:
hardware: Espressif ESP32-LyraTv4.3
IDF: v4.1.2
ADF: v2.6

Thanks a lot!
Cheers
JR