ADF Audio Pipeline Decoding Speed (AUD-4653)

[DerPicknicker]

Hi!

I need the help again of the experts. I use a custom board with a custom board config which works fine. My Code also works fine. But for me it's not clear how the Audio Pipeline works and how long the Pipeline needs to decode an MP3-Stream.

Here is the Piece of Code that decodes the MP3-Stream:

ESP_LOGI(TAG, "stream_task is starts");
    ESP_LOGI(TAG, "[2.6] Set up  uri (http as http_stream, mp3 as mp3 decoder, and default output is i2s)");
    audio_element_set_uri(http_stream_reader, url);
    // Example of using an audio event -- START
    ESP_LOGI(TAG, "[ 4 ] Set up  event listener");
    audio_event_iface_cfg_t evt_cfg = AUDIO_EVENT_IFACE_DEFAULT_CFG();
    audio_event_iface_handle_t evt = audio_event_iface_init(&evt_cfg);

    ESP_LOGI(TAG, "[4.1] Listening event from all elements of pipeline");
    audio_pipeline_set_listener(pipeline, evt);

    ESP_LOGI(TAG, "[4.2] Listening event from peripherals");
    audio_event_iface_set_listener(esp_periph_set_get_event_iface(set), evt);

    ESP_LOGI(TAG, "[ 5 ] Start audio_pipeline");
    audio_pipeline_run(pipeline);

    start_time = xTaskGetTickCount();
    while (1)
    {
        audio_event_iface_msg_t msg;
        esp_err_t ret = audio_event_iface_listen(evt, &msg, portMAX_DELAY);
        //vTaskDelay(pdMS_TO_TICKS(250));
        if (ret != ESP_OK)
        {
            ESP_LOGE(TAG, "[ * ] Event interface error : %d", ret);
            continue;
        }

        if (msg.source_type == AUDIO_ELEMENT_TYPE_ELEMENT && msg.source == (void *)mp3_decoder && msg.cmd == AEL_MSG_CMD_REPORT_MUSIC_INFO)
        {
            audio_element_info_t music_info = {0};
            audio_element_getinfo(mp3_decoder, &music_info);

            ESP_LOGI(TAG, "[ * ] Receive music info from mp3 decoder, sample_rates=%d, bits=%d, ch=%d",
                     music_info.sample_rates, music_info.bits, music_info.channels);

            i2s_stream_set_clk(i2s_stream_writer, music_info.sample_rates, music_info.bits, music_info.channels);

            continue;
            //int timebefore =  esp_log_timestamp(); 
            //vTaskDelay(50000 / portTICK_PERIOD_MS); // Adjust the delay as needed
            //int diff = (esp_log_timestamp()-timebefore);
            //ESP_LOGI(TAG, "MP3 Time diff: %i", diff);
        }

        /* Stop when the last pipeline element (i2s_stream_writer in this case) receives stop event */
        if (msg.source_type == AUDIO_ELEMENT_TYPE_ELEMENT && msg.source == (void *)i2s_stream_writer && msg.cmd == AEL_MSG_CMD_REPORT_STATUS && (((int)msg.data == AEL_STATUS_STATE_STOPPED) || ((int)msg.data == AEL_STATUS_STATE_FINISHED)))
        {
            ESP_LOGW(TAG, "[ * ] Stop event received");
            break;
        }
    }

As you can see there are two places where I added some Delays at the beginning of the While-Loop and under this Statement: i2s_stream_set_clk

The Audio plays only slower if I put the Delay at the beginning of the While-Loop.

The next Test was to create two tasks, which are controlled by FreeRTOS: Task 1 Playing MP3-Stream Task 2 Checks if Task 2 is running if that's the case make also a Delay.

void taskSwitchingTestTask()
{
    while (1)
    {

        if (xTaskGetCurrentTaskHandle() == stream_task)
        {
            ESP_LOGI(TAG, "taskSwitchingTestTask is not running");
        }
        else
        {
            ESP_LOGI(TAG, "taskSwitchingTestTask is running");
            int timebefore =  esp_log_timestamp(); 
            vTaskDelay(1000 / portTICK_PERIOD_MS); // Adjust the delay as needed
            int diff = (esp_log_timestamp()-timebefore);
            ESP_LOGI(TAG, "Time diff: %i", diff);
        }

    }
}

Here are my main Questions:

• How long is the ESP32 busy to decode an MP3-Stream or in Other Words how much capacities do I have for other Tasks on the same core where the Decoding happens?
• Why does the second test with the Delay not work as expected ? I tried also way bigger values than 1000 and the Stream still works without any issues
• How can I measure the CPU-Time which is available beside the Decoding-Task?

Thank you in advance for your Support!

[TempoTian]

I think what your needs is: https://github.com/espressif/esp-adf/blob/master/components/audio_sal/audio_sys.c#L66 Please enable CONFIG_FREERTOS_VTASKLIST_INCLUDE_COREID && CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS in menuconfig. vTaskDelay only yield cpu and let it to schedule to other tasks. So it does not affect the decode speed. Decoding is executed in decode element which actually is a task, you can measure the tasks loadings use: audio_sys_get_real_time_stats The IDLE task means the remaining cpu of certain core.

[DerPicknicker]

@TempoTian .. Thank you for the fast response. I will give an update to you.

[DerPicknicker]

@TempoTian ..

Here is my Update:

First I tried your Function: audio_sys_get_real_time_stats

this doesn't print out anything. and yes I checked the Menuconfig I enabled both settings you mentioned. After I did some research I found this Example from the IDF-Github: https://github.com/espressif/esp-idf/blob/master/examples/system/freertos/real_time_stats/main/real_time_stats_example_main.c

I copied the Function print_real_time_stats() and now I got some Output:

| Task | Run Time | Percentage | taskSwitchingTe | 20728 | 0% | IDLE | 1467102 | 36% | IDLE | 1991847 | 49% | tiT | 31876 | 0% | stream_task | 0 | 0% | Tmr Svc | 0 | 0% | wifi | 101996 | 2% | esp_timer | 5272 | 0% | ipc0 | 0 | 0% | mp3 | 347929 | 8% | http | 27810 | 0% | i2s | 26357 | 0% | ipc1 | 0 | 0% | sys_evt | 0 | 0%

Why do I have two Idle-States? And where does the Decoding runs? I want to assign the Decoding to one specific core. Is this possible in the current release of ADF? Can we figure out why the Function you linked to me is not printing the Task load?

Many thanks for your time!

EDIT1: I found how to change the Core but one of the Cores still is only 49% in Idle .. This cannot be true. It would be great if we can figure out why the Code is not assigned to the right core.

In the main.c I just call a function which only creates the Tasks on the specified core and it should start the stream on the core. Sadly this does not happen - one Core is still 49% in use.

[TempoTian]

If enable config not work you can attach your log to help locate the NG point. Two IDLE task means have two core, for it shows the total usage, each cpu maximum is 50%, 49% means almost all idle. Decoding is run as task mp3 which use 8% cpu. Decode core can be configured such as using MP3: https://github.com/espressif/esp-adf-libs/blob/01336f1908bfd0f3f567382d40e872eaa969884d/esp_codec/include/codec/mp3_decoder.h#L23

[DerPicknicker]

If enable config not work you can attach your log to help locate the NG point.

Thank you @TempoTian for the explanation. I want to run the audio things on one core. The other core is needed for hardware with strict timings. This is why I ask how to configure all these things. Could you imagine why the other core is also used by 50%?

May I ask what do you mean with NG-Point? Is that the log provided by the flash monitor?

[DerPicknicker]

Push @TempoTian 😉👍🏻

[TempoTian]

I have attached the setting you can change decode core setting as following: mp3_decoder_cfg_t mp3_cfg = DEFAULT_MP3_DECODER_CONFIG(); mp3_cfg .task_core = 1; // such as you want to pin to core 1 IDLE means not used, it's 50% means core 1 is not used at all. Yes, you can catch log use monitor.

[DerPicknicker]

@TempoTian thank you for your time and your response! I will try to pin all audio function to one core. This should increase the idle-percentage of one core. Hope this will bring me to a clear picture. I will attach the log for you.

Many thanks 👍🏻

[jason-mao]

This topic has become inactive so I'm going to close the issue. Please reopen this if you have any questions or need any further assistance.