input key service causes esp_timer to consume 50% of CPU time on ESP-LyraTv4.3 (AUD-5465)

[bs-eng]

Environment

• Audio development kit: ESP32-LyraT
• Audio kit version: v4.3
• Module or chip used: ESP32-WROVER-E
• IDF version: v5.1.2 (also others before that)
• ADF version : v2.6
• Build system: CMake
• Running log: audioapp_115k__custom_app_timer_load_log.txt + other logs, see below
• Compiler version: esp_tools.txt
• Operating system: Windows10
• (Windows only) Environment type: ?
• Using an IDE?: Eclipse with Espressif IDF plugin
• Power supply: USB

Problem Description

Hello! I ran into a speed issue with my code. The code runs so slow that audio playback is stuttering on all audio files I play. It seems that the input key service is consuming large amounts of CPU time (~50%).

Expected Behavior

The CPU load of the timer should be much lower, to a degree that audios play without stuttering. Using ADFv2.4 and IDFv3.3 (which is what our code originally was compiled on) the system ran smooth without any stuttering audios.

Actual Behavior

See also thread on Espressif forum for additional details: esp_timer consumes 50% of CPU time, please help 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:

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

From there I drilled down to find out what is going on. I ended up disabling all timers in my application. Still the problem persisted. So I got more output from the timer task using esp_timer_dump(). This showed that the "touch filter timer" is using massive amount of CPU time in its callback function.

Steps to Reproduce

From there I drilled down more and used two plain examples from from the ESP-ADFv2.6 on a ESP-Lyratv4.3 called pipeline_play_sdcard_music and pipeline_sdcard_mp3_control and added support for:

• esp_timer_dump()
• uxTaskGetSystemState() (optional for reproducing)

in order to collect system stats. Both projects were build in a standard way

1. import example project
2. add esp_timer_dump() and uxTaskGetSystemState() - see code at bottom
3. configure sdkconfig
4. build
5. flash to ESP-LyraTv4.3
6. run

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().

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().

W (79193) pipeline_sdcard_mp3_control:  #            task name  core free stack   run time      in %%
W (79213) pipeline_sdcard_mp3_control:  0                 main     0       1404   19191007         24%
W (79213) pipeline_sdcard_mp3_control:  1                 IDLE     1        916   77714232         99%
W (79223) pipeline_sdcard_mp3_control:  2                 IDLE     0        920   12753128         16%
W (79243) pipeline_sdcard_mp3_control:  3           esp_periph     0       2312     362137         <1%
W (79243) pipeline_sdcard_mp3_control:  4              Tmr Svc     0       1116     125350         <1%
W (79253) pipeline_sdcard_mp3_control:  5               filter     0       2988    1143378          1%
W (79273) pipeline_sdcard_mp3_control:  6                  i2s     0       2572     546368         <1%
W (79273) pipeline_sdcard_mp3_control:  7      input_key_servi     1       1168      15744         <1%
W (79283) pipeline_sdcard_mp3_control:  8                 ipc1     1        488      60194         <1%
W (79303) pipeline_sdcard_mp3_control:  9                 file     0       2012     128207         <1%
W (79303) pipeline_sdcard_mp3_control: 10            esp_timer     0       3424   40960276         52%
W (79313) pipeline_sdcard_mp3_control: 11                  mp3     0       3876    2532796          3%
W (79333) pipeline_sdcard_mp3_control: 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?

Thanks a lot! Cheers JR

Edit: The same examples were reproduced today on a ESP32-S3-Korvo-2 v3.1. The effect of the timer consuming so much CPU resources does not appear. To me this indicates that there is something wrong in the configuration of the board ESP32-LyraTv4.3. What could that be?

Code to Reproduce This Issue

Function to get the task stats dump:

void getRunTimeStats( void )
{
TaskStatus_t *pxTaskStatusArray;
volatile UBaseType_t uxArraySize, x;
uint32_t ulTotalRunTime, ulStatsAsPercentage;

    ESP_LOGW( TAG, "Debug code, remove %s before production!", __func__ );

    // Take a snapshot of the number of tasks in case it changes while this
    // function is executing.
    uxArraySize = uxTaskGetNumberOfTasks();

    // Allocate a TaskStatus_t structure for each task.  An array could be
    // allocated statically at compile time.
    pxTaskStatusArray = pvPortMalloc( uxArraySize * sizeof( TaskStatus_t ) );

    if( pxTaskStatusArray != NULL )
    {
        // print table header
        ESP_LOGW( TAG, " # %20s %5s %10s %10s %10s", "task name", "core", "free stack", "run time", "in %%");

        // Generate raw status information about each task.
        uxArraySize = uxTaskGetSystemState( pxTaskStatusArray, uxArraySize, &ulTotalRunTime );

        // For percentage calculations.
        ulTotalRunTime /= 100UL;

        // Avoid divide by zero errors.
        if( ulTotalRunTime > 0 )
        {
            // For each populated position in the pxTaskStatusArray array,
            // format the raw data as human readable ASCII data
            for( x = 0; x < uxArraySize; x++ )
            {
                // What percentage of the total run time has the task used?
                // This will always be rounded down to the nearest integer.
                // ulTotalRunTimeDiv100 has already been divided by 100.
                ulStatsAsPercentage = pxTaskStatusArray[ x ].ulRunTimeCounter / ulTotalRunTime;

                if( ulStatsAsPercentage > 0UL )
                {
                    ESP_LOGW( TAG, "%2i %20s %5i %10lu %10lu %10lu%%", x, pxTaskStatusArray[ x ].pcTaskName, xTaskGetAffinity(pxTaskStatusArray[ x ].xHandle), pxTaskStatusArray[ x ].usStackHighWaterMark, pxTaskStatusArray[ x ].ulRunTimeCounter, ulStatsAsPercentage );
                }
                else
                {
                    // If the percentage is zero here then the task has
                    // consumed less than 1% of the total run time.
                    ESP_LOGW( TAG, "%2i %20s %5i %10lu %10lu         <1%%", x, pxTaskStatusArray[ x ].pcTaskName, xTaskGetAffinity(pxTaskStatusArray[ x ].xHandle), pxTaskStatusArray[ x ].usStackHighWaterMark, pxTaskStatusArray[ x ].ulRunTimeCounter );
                }
            }
        }

        // The array is no longer needed, free the memory it consumes.
        vPortFree( pxTaskStatusArray );
    }
    ESP_ERROR_CHECK(esp_timer_dump(stdout));
}

[hbler99]

We are grateful for your input; however, this issue was not identified during our testing process.