[ESP32] Low performance of esp-idf build comparing to arduino one

[osnwt]

The problem

The same code built for ESP32 with esp-idf framework is much slower than the same code built with arduino framework.

I found the issue a month ago, when after one of ESPHome updates the same code dealing with display was slowed down too much being built with esp-idf (0.61s comparing to 0.13s for arduino per display refresh cycle). Before update it had near the same performance. I took a free ESP32 board and after init added very simple lambda to it. And yes, it is much slower now with esp-idf.

It seems there is some regression, and I wonder if someone else sees the same issue?

Tricks in the sample code with logging are just to prevent a compiler optimization of empty loops.

Which version of ESPHome has the issue?

2023.12.6, 2023.12.7

What type of installation are you using?

Home Assistant Add-on

Which version of Home Assistant has the issue?

2024.1.3

What platform are you using?

ESP32-IDF

Board

esp32dev, lolin32, maybe others

Component causing the issue

display (slow refresh), simple lambda loop, etc

Example YAML snippet

esp32:
  board: esp32dev
  framework:
    type: arduino
    #type: esp-idf

interval:
  - interval: 5s
    then:
      - lambda: |-
          auto start = millis();
          const uint32_t imax = 30L;
          const uint32_t jmax = 100000L;
          for (uint32_t i = 0; i <= imax; i++) {
            for (uint32_t j = 0; j <= jmax; j++) {
              if (i == imax && j == jmax) {
                ESP_LOGI("TIME", "Match");
              }
            }
          }
          auto finish = millis();
          ESP_LOGI("TIME", "s: %d, f: %d, delta: %d", start, finish, finish - start);

Anything in the logs that might be useful for us?

type: arduino

[18:50:51][I][TIME:044]: Match
[18:50:51][I][TIME:049]: s: 18946, f: 19109, delta: 163
[18:50:51][W][component:214]: Component interval took a long time for an operation (0.17 s).
[18:50:51][W][component:215]: Components should block for at most 20-30ms.

type: esp-idf

[18:48:24][I][TIME:044]: Match
[18:48:24][I][TIME:049]: s: 14460, f: 14701, delta: 241
[18:48:24][W][component:214]: Component interval took a long time for an operation (0.24 s).
[18:48:24][W][component:215]: Components should block for at most 20-30ms.

Additional information

The difference is much higher when used for real components like

display:
  - platform: st7735
    model: "INITR_18BLACKTAB"

type: arduino

[14:34:45][W][component:214]: Component interval took a long time for an operation (0.14 s).
[14:34:45][W][component:215]: Components should block for at most 20-30ms.

type: esp-idf

[14:34:15][W][component:214]: Component interval took a long time for an operation (0.62 s).
[14:34:15][W][component:215]: Components should block for at most 20-30ms.

0.62s blocking time for display is almost no go. Screen updates are so slow, that you see how it updates when you change display pages.

Seems to be a critical bug, IMHO.

[osnwt]

What happens? New ESPHome update (2023.12.8), new timings of the same code:

type: arduino

[16:26:01][W][graph:121]: Graphing reducing y-scale to prevent too many gridlines
[16:26:01][W][component:214]: Component interval took a long time for an operation (0.14 s).

type: esp-idf

[16:22:32][W][graph:121]: Graphing reducing y-scale to prevent too many gridlines
[16:22:33][W][component:214]: Component interval took a long time for an operation (0.87 s).

Now 0.87 s vs 0.14 s of the same code. Is it a joke?

[osnwt]

Looks like something has been "optimized" related to power management in the latest esp-idf versions.

1. Tried to log CPU frequency for both configurations. It shows 240MHz for arduino, 160MHz for esp-idf.
2. Tried to lower the CPU frequency for arduino platform. Even at 80MHz it still works, and display refresh takes 0.28s instead of 0.14 with 240MHz (compare to 0.62-0.88 for esp-idf at 160MHz). So it is not (only) CPU freq.
3. Tried to downgrade ESPHome addon. It did not help since it still installs latest available platform_version: 5.4.0 and version: 4.4.5. So even with old ESPHome addon 2023.8 I still have the same issue.

Wonder why nobody noticed it yet.

[kev300]

How can I check the current cpu frequency? I'm also curious because I'm using esp-idf and it is slow sometimes...

[osnwt]

@kev300 It's a kind of dynamic and different peripherals may have own frequencies. But an overall, you may try this:

ESP_LOGI("CPU", "CPU freq: %d", esp_clk_cpu_freq());

Just compiled the same code with latest ESPHome Home Assistant plugin updates: nothing changed.

# Arduino framework
[17:30:26][I][CPU:360]: CPU freq: 240000000
[17:30:26][W][component:232]: Component interval took a long time for an operation (140 ms).
[17:30:26][W][component:233]: Components should block for at most 30 ms.

# ESP-IDF framework
[17:27:21][I][CPU:360]: CPU freq: 160000000
[17:27:22][W][component:232]: Component interval took a long time for an operation (630 ms).
[17:27:22][W][component:233]: Components should block for at most 30 ms.

[kev300]

error: 'esp_clk_cpu_freq' was not declared in this scope

I have a standard ESP32

esp32: board: nodemcu-32s framework: type: esp-idf

[osnwt]

Add into your config folder: /root/config/esphome/include/clk.h with the following content:

// For uint32_t esp_clk_cpu_freq() returning CPU frequence in Hz
// Usage: ESP_LOGI("CPU", "CPU freq: %d", esp_clk_cpu_freq());

#include "soc/esp32/clk.h"

And into your project config:

esphome:
  includes: include/clk.h

[kev300]

thanks, I can confirm that it's running at 160MHz and I cannot increase it via board_build.f_cpu

[osnwt]

And, still, this is not a root cause, because 630/140=4.5 times slower, not 240/160=2.125...

[kev300]

I know, but at least a higher frequency could help a little...

Did you try playing with some esp-idf options like here?

https://community.home-assistant.io/t/slowing-down-an-esp32-with-esphome/332600/12

[osnwt]

I tried to play with frequency, had not succeeded and stopped (see my earlier comments above). Moreover, I tried to rollback ESPHome plugin version and use older platform. No luck, it seems that different ESPHome releases still use a kind of "latest available" esp-idf platform, not pinned to a some well defined one. And when I tried to set them explicitly, I had incompatibilities and build errors.

Anyway, if no one is interested, no one noticed... Well, I am ok to stay with arduino framework. I am happy to help, but I do not develop the esp-idf or esphome platforms. So I have no more time to ring all bells.

[benediktkr]

I think I have figured this out by looking through the generated sdkconfig.${name} files in build_dir.

Note that the default esp-idf version that ESPHome uses currently is 4.4.6 (also set as platformio/framework-espidf in platformio.ini - probably pulled in as a dependency of it). Since the APIs for this have changed quite a bit in the current releases of esp-idf, we need to read the esp-idf documentation for version 4.4.6, and look the source for esp-idf at the release/v4.4 tag.

The relevant sdkconfig options for ESP32-S2:

• CONFIG_ESP32S2_DEFAULT_CPU_FREQ_240
• CONFIG_ESP32S2_DEFAULT_CPU_FREQ_MHZ

For a "regular" ESP32, the sdkconfig options are:

• CONFIG_ESP32_DEFAULT_CPU_FREQ_240
• CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ

Configuring the esp32 component on ESP32-S2:

esp32:
  variant: ESP32S2
  framework: 
    type: esp-idf
    sdkconfig_options:
      # ESP32
      CONFIG_ESP32_DEFAULT_CPU_FREQ_240: "y"
      CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ: "240"

I'm able to read it back with:

#include "esphome.h"
#include "soc/esp32/clk.h"

class CPUFreq : public Component, public Sensor {
 public:
  SysInfo() : Component() {
    unit_of_measurement_ = "MHz";
    entity_category_ = EntityCategory::ENTITY_CATEGORY_DIAGNOSTIC;
    device_class_ = "frequency";
    state_class_ = StateClass::STATE_CLASS_MEASUREMENT;
  }
  void setup() override {
    int cpu_freq = get_cpu_freq();
    publish_state(cpu_freq);
  }

The soc/esp32clk.h file includes esp_private/esp_clk.h, and esp_clk.c includes esp32/clk.h so I think thats where the esp_clk_cpu_freq function from above is defined. It seems to be returning either a value thats burned into the chips ROM? But there's also references to changing it there.

That's where I get stuck though, and I haven't be able to figure it out if its possible to change the CPU frequency at runtime either.

[kev300]

OK, with those both options my ESP is now running with 240MHz, but I did not benchmark it, yet. Thanks

[daztucker]

Not sure if this is it, but https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/kconfig.html#config-compiler-optimization says about CONFIG_COMPILER_OPTIMIZATION that the '"Performance" setting will add the -O2 flag to CFLAGS.' The default is not specified, but all of the other options talk about adding flags which implies that the default is to not add anything, which may mean it defaults to a completely unoptimized build?

[daztucker]

Not sure if this is it

I got curious and did some experimentation and no variation of these flags seemed to make any difference, so I don't think this is it.