ArduinoESP32 v2.0.4 conflicts with SPI class because PSRAM uses VSPI(SPI3)

[lovyan03]

Board

M5Stack Fire ( ESP32 with PSRAM 4MByte(32Mbit) )

Device Description

No special hardware is required.

Hardware Configuration

I believe that an ESP32 with 4MByte PSRAM can probably reproduce the problem.

Version

v2.0.4

IDE Name

ArduinoIDE or Platform IO

Operating System

Windows 10

Flash frequency

40MHz or 80MHz

PSRAM enabled

yes

Upload speed

1.5Mbps

Description

I would like to thank all of you for the great job you are doing maintaining this project.

I am unable to decide whether I should submit this Issue to ESP-IDF or ArduinoESP32 and would like to discuss it.

Starting with ESP-IDF ver4.4, HSPI or VSPI is required for PSRAM operation when the following conditions are met.

• PSRAM 32Mbit (4MB) enabled
• PSRAM freq = 80MHz
• FLASH freq = 80MHz

information is here.
https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/external-ram.html?highlight=occupy_#failure-to-initialize

Looking at the SDK CONFIG for ArduinoESP32 v2.0.4, the flag CONFIG_SPIRAM_OCCUPY_VSPI_HOST=y is set.

https://github.com/espressif/arduino-esp32/blob/master/tools/sdk/esp32/sdkconfig#L687

In other words, VSPI is used by PSRAM when the above conditions are met.

On the other hand, the ArduinoESP32 SPI instance uses VSPI by default.
This causes the program to crash if all of the following conditions are met.

• ArduinoESP32 v2.0.4 (No problem until v2.0.3.)
• ESP32 with 4MByte PSRAM (e.g. No probrem with 8MByte PSRAM.)
• PSRAM enabled (No probrem with PSRAM disabled.)
• Use SPI instance, for example, with SD cards, etc.

I confirmed that the Issue occur with M5Stack Fire (4MB PSRAM).
I confirmed that the Issue does not occur with M5Stack Core2 (8MB PSRAM).

Presumably, with 4MB PSRAM, the following conditional branch is executed and VSPI is used.

https://github.com/espressif/esp-idf/blob/release/v4.4/components/esp_hw_support/port/esp32/spiram_psram.c#L954-L966

Referring to the log below, it seems that up to Arduino ESP32 v2.0.3, both Flash and PSRAM are set at 40MHz, but in Arduino ESP32 v2.0.4, both Flash and PSRAM are set at 80MHz.
I do not know what measures are desirable, but I wonder if it might be a good idea to set the PSRAM speed to 40MHz through the CONFIG setting?

Sketch

#include <Arduino.h>
#include <SD.h>

void setup()
{
  delay(2000);

#if defined ( CONFIG_ESPTOOLPY_FLASHMODE )
  ESP_LOGE("DEBUG", "FLASH mode:%s", CONFIG_ESPTOOLPY_FLASHMODE);
#endif

#if defined ( CONFIG_ESPTOOLPY_FLASHFREQ )
  ESP_LOGE("DEBUG", "FLASH freq:%s", CONFIG_ESPTOOLPY_FLASHFREQ);
#endif

#if defined ( CONFIG_SPIRAM_SPEED_40M )
  ESP_LOGE("DEBUG", "SPIRAM freq:40MHz");
#elif CONFIG_SPIRAM_SPEED_80M
  ESP_LOGE("DEBUG", "SPIRAM freq:80MHz");
#else
  ESP_LOGE("DEBUG", "SPIRAM freq:unknown");
#endif

#if defined ( CONFIG_SPIRAM_OCCUPY_VSPI_HOST )
  ESP_LOGE("DEBUG", "CONFIG_SPIRAM_OCCUPY_VSPI_HOST enabled");
#elif defined ( CONFIG_SPIRAM_OCCUPY_HSPI_HOST )
  ESP_LOGE("DEBUG", "CONFIG_SPIRAM_OCCUPY_HSPI_HOST enabled");
#else
  ESP_LOGE("DEBUG", "CONFIG_SPIRAM_OCCUPY not set");
#endif

  ESP_LOGE("DEBUG", "esp_spiram_get_size : %d", esp_spiram_get_size());
  ESP_LOGE("DEBUG", "esp_spiram_get_cs_io : %d", esp_spiram_get_cs_io());
  ESP_LOGE("DEBUG", "esp_spiram_get_chip_size : %d", esp_spiram_get_chip_size());

  // for M5Stack FIRE SD SPI setting.
  SPI.begin(GPIO_NUM_18, GPIO_NUM_19, GPIO_NUM_23);

  // for M5Stack Core2 SD SPI setting.
//SPI.begin(GPIO_NUM_18, GPIO_NUM_38, GPIO_NUM_23);
  // ( no need insert sd card. )
  SD.begin(GPIO_NUM_4, SPI, 20000000); // Arduino ESP32 v2.0.4: crash here
}

void loop()
{
  delay(1000);
  auto ptr = heap_caps_malloc(4096, MALLOC_CAP_SPIRAM);
  ESP_LOGE("DEBUG", "ptr:%08x", ptr);
}

Debug Message (Arduino ESP32 v2.0.4 with flash 40MHz setting)

16:53:39.177 > ets Jun  8 2016 00:22:57
16:53:39.178 >
16:53:39.178 > rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
16:53:39.178 > configsip: 0, SPIWP:0xee
16:53:39.178 > clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
16:53:39.178 > mode:DIO, clock div:2
16:53:39.178 > load:0x3fff0030,len:1184
16:53:39.178 > load:0x40078000,len:13132
16:53:39.178 > load:0x40080400,len:3036
16:53:39.178 > entry 0x400805e4
16:53:39.325 > ���mum����2-hal-cpu.c:214] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
16:53:39.765 > [   449][I][esp32-hal-psram.c:96] psramInit(): PSRAM enabled
16:53:41.841 > [  2485][E][psram_spi_test.cpp:9] setup(): [DEBUG] FLASH mode:dio
16:53:41.842 > [  2486][E][psram_spi_test.cpp:13] setup(): [DEBUG] FLASH freq:80m
16:53:41.842 > [  2486][E][psram_spi_test.cpp:19] setup(): [DEBUG] SPIRAM freq:80MHz
16:53:41.842 > [  2492][E][psram_spi_test.cpp:25] setup(): [DEBUG] CONFIG_SPIRAM_OCCUPY_VSPI_HOST enabled
16:53:41.842 > [  2500][E][psram_spi_test.cpp:32] setup(): [DEBUG] esp_spiram_get_size : 4194304
16:53:41.842 > [  2507][E][psram_spi_test.cpp:33] setup(): [DEBUG] esp_spiram_get_cs_io : 16
16:53:41.842 > [  2514][E][psram_spi_test.cpp:34] setup(): [DEBUG] esp_spiram_get_chip_size : 1
16:53:41.886 > Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
16:53:41.886 >
16:53:41.886 > Core  1 register dump:
16:53:41.886 > PC      : 0x4008d65d  PS      : 0x00060a30  A0      : 0x8008deea  A1      : 0x3ffb2580
16:53:41.886 > A2      : 0xffffffff  A3      : 0xffffffff  A4      : 0x00000005  A5      : 0x00000000
16:53:41.886 > A6      : 0x3ffb8ac4  A7      : 0x00000000  A8      : 0x00000015  A9      : 0x00000008
16:53:41.886 > A10     : 0x0000002f  A11     : 0x0000693c  A12     : 0x00000011  A13     : 0x00001868
16:53:41.886 > A14     : 0x00000000  A15     : 0x3ffc1c34  SAR     : 0x00000009  EXCCAUSE: 0x0000001c  
16:53:41.930 > EXCVADDR: 0x00000033  LBEG    : 0x40087504  LEND    : 0x4008750f  LCOUNT  : 0x00000000
16:53:41.930 >
16:53:41.930 > Backtrace:0x4008d65a:0x3ffb25800x4008dee7:0x3ffb25a0 0x4008e15c:0x3ffb25c0 0x4008375e:0x3ffb25e0 0x40083771:0x3ffb2610 0x4008381a:0x3ffb2630 0x400e0aed:0x3ffb2680 0x400e1ad0:0x3ffb26a0 0x400d2b7b:0x3ffb2780 0x400d1942:0x3ffb27c0 0x400d14e9:0x3ffb27f0 0x400d461f:0x3ffb2820
16:53:41.930 >
16:53:41.930 >
16:53:41.930 > ELF file SHA256: 0000000000000000
16:53:41.930 >
16:53:41.930 > Rebooting...
16:53:41.956 > ets Jun  8 2016 00:22:57
16:53:41.956 >
16:53:41.956 > rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)

Debug Message (Arduino ESP32 v2.0.3 with flash 80MHz setting)

16:48:41.796 > ets Jun  8 2016 00:22:57
16:48:41.796 >
16:48:41.796 > rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
16:48:41.796 > configsip: 0, SPIWP:0xee
16:48:41.796 > clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
16:48:41.796 > mode:DIO, clock div:1
16:48:41.796 > load:0x3fff0030,len:1344
16:48:41.796 > load:0x40078000,len:13516
16:48:41.796 > load:0x40080400,len:3604
16:48:41.796 > entry 0x400805f0
16:48:41.909 > [��mum����2-hal-cpu.c:214] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
16:48:42.757 > [   852][I][esp32-hal-psram.c:96] psramInit(): PSRAM enabled
16:48:44.843 > [  2898][E][psram_spi_test.cpp:9] setup(): [DEBUG] FLASH mode:dio
16:48:44.843 > [  2899][E][psram_spi_test.cpp:13] setup(): [DEBUG] FLASH freq:40m
16:48:44.843 > [  2899][E][psram_spi_test.cpp:17] setup(): [DEBUG] SPIRAM freq:40MHz
16:48:44.843 > [  2905][E][psram_spi_test.cpp:29] setup(): [DEBUG] CONFIG_SPIRAM_OCCUPY not set
16:48:44.843 > [  2913][E][psram_spi_test.cpp:32] setup(): [DEBUG] esp_spiram_get_size : 4194304
16:48:44.843 > [  2920][E][psram_spi_test.cpp:33] setup(): [DEBUG] esp_spiram_get_cs_io : 16
16:48:44.843 > [  2927][E][psram_spi_test.cpp:34] setup(): [DEBUG] esp_spiram_get_chip_size : 1
16:48:44.850 > [  2937][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:44.943 > [  3039][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:45.044 > [  3139][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:45.164 > [  3238][E][sd_diskio.cpp:199] sdCommand(): Card Failed! cmd: 0x00
16:48:45.164 > [  3239][W][sd_diskio.cpp:516] ff_sd_initialize(): GO_IDLE_STATE failed
16:48:45.164 > [  3240][E][sd_diskio.cpp:802] sdcard_mount(): f_mount failed: (3) The physical drive cannot work
16:48:45.164 > [  3249][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:45.259 > [  3354][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:45.359 > [  3454][W][sd_diskio.cpp:174] sdCommand(): no token received
16:48:45.459 > [  3553][E][sd_diskio.cpp:199] sdCommand(): Card Failed! cmd: 0x00
16:48:46.458 > [  4553][E][psram_spi_test.cpp:46] loop(): [DEBUG] ptr:3f800874
16:48:47.459 > [  5553][E][psram_spi_test.cpp:46] loop(): [DEBUG] ptr:3f801884

Other Steps to Reproduce

No response

I have checked existing issues, online documentation and the Troubleshooting Guide

• I confirm I have checked existing issues, online documentation and Troubleshooting guide.

[P-R-O-C-H-Y]

@me-no-dev Can you take a look? Seems reasonable to fix this for 2.0.5 release.

[me-no-dev]

Fixed in lib-builder. Will be part of 2.0.5 :)

[lovyan03]

@me-no-dev
Thanks for your quick fix!
but, sorry, this change only changes the dependency to HSPI, so a user application that wants to use all of PSRAM, VSPI and HSPI will still crash, won't it?
In ArduinoIDE and PlatformIO, if the speed of PSRAM can be set by the user, this may not be a problem, but I am concerned.

I have an idea.
It would probably require an addition to the ESP-IDF, but it would implement the behavior that "if PSRAM is OK, it will run at 80 MHz; if it is not, it will run at 40 MHz." This behavior should be implemented so that an additional SPI peripheral is not required.
I don't know how many users would be willing to use 80MHz even if it consumes one SPI peripheral, but I think there are many users who would be fine with 40MHz if it consumes an SPI peripheral.

If necessary I will make a proposal to the ESP-IDF repository.

[tobozo]

please reopen, this is not a real fix, actually more devices are affected after applying this (e.g. LoLin D32-Pro, TTGO-TWatch)

the issue is with forcing 80MHz on psram, ideally the correct sequence should test "if 80MHz fails then try 40MHz"

[lovyan03]

Oops, sorry... I made a mistake in my first post.
I pasted two logs, but the title of the logs was incorrect.

The correct title is as follows

1st log :
Debug Message (Arduino ESP32 v2.0.4 with flash 40MHz setting)

2nd log :
Debug Message (Arduino ESP32 v2.0.3 with flash 80MHz setting)

Look at the clock div value in the log.

In the log of v2.0.4, the output of the conditional branch shows 80MHz even though it is set to 40MHz (clock div:2).
In the log of v2.0.3, the output of the conditional branch shows 40MHz even though it is set to 80MHz (clock div:1).

I am not sure why this difference has occurred, is there some other problem that is occurring?

[me-no-dev]

• CONFIG_ values are not necessarily correct at all times in Arduino. ESP-IDF is precompiled.
• The fix makes SPI work when PSRAM is at 80MHz. (because VSPI is the default SPI in Arduino for ESP32)
• If you want all ports available, select Flash to be 40MHz QIO (PSRAM will also be 40MHz)
• @tobozo if you want some different way of booting PSRAM, please take that to ESP-IDF. In Arduino we just call init

[TD-er]

• If you want all ports available, select Flash to be 40MHz QIO (PSRAM will also be 40MHz)

And what about when no PSRAM support is enabled in a build?
What I'm seeing is that the SPI clock sometimes switches to 80 MHz, even though no PSRAM is connected and nothing other than the flash is connected to this bus.
N.B. this is regardless the SPI flash frequency as it sticks to 40 MHz for the rest of the time on my board no matter flash tool I use and flash frequency setting.
See: #7140 (comment)

[tobozo]

If you want all ports available, select Flash to be 40MHz QIO (PSRAM will also be 40MHz)

@me-no-dev ESP.getFlashChipMode() returns 0x02 (DIO) and seems unaffected by the selected Flash Mode menu option.

something broken in platform.txt maybe?

[lovyan03]

@tobozo @me-no-dev
I too have confirmed this problem.
I try :QIO , QOUT , DIO , DOUT .
result:DIO , DOUT , DIO , DOUT .

QIO and QOUT do not appear to be set correctly.

I tested with both ArduinoIDE and PlatformIO and the results were the same for both.

I have my doubts that the description in boards.txt is correct.

For example...

arduino-esp32/boards.txt

Lines 651 to 662 in c93bf11

	esp32.menu.FlashMode.qio=QIO
	esp32.menu.FlashMode.qio.build.flash_mode=dio
	esp32.menu.FlashMode.qio.build.boot=qio
	esp32.menu.FlashMode.dio=DIO
	esp32.menu.FlashMode.dio.build.flash_mode=dio
	esp32.menu.FlashMode.dio.build.boot=dio
	esp32.menu.FlashMode.qout=QOUT
	esp32.menu.FlashMode.qout.build.flash_mode=dout
	esp32.menu.FlashMode.qout.build.boot=qout
	esp32.menu.FlashMode.dout=DOUT
	esp32.menu.FlashMode.dout.build.flash_mode=dout
	esp32.menu.FlashMode.dout.build.boot=dout

esp32.menu.FlashMode.qio=QIO
esp32.menu.FlashMode.qio.build.flash_mode=dio  <<= why dio ?
esp32.menu.FlashMode.qio.build.boot=qio

esp32.menu.FlashMode.qout=QOUT
esp32.menu.FlashMode.qout.build.flash_mode=dout  <<= why dout ?
esp32.menu.FlashMode.qout.build.boot=qout

I changed this description to qio and qout, respectively, to test it out.

Test code:

#include <Arduino.h>
void setup(void)
{
  delay(1000);
  printf("getFlashChipMode : %d\n",ESP.getFlashChipMode());
  printf("getFlashChipSize : %d\n",ESP.getFlashChipSize());
  printf("getFlashChipSpeed : %d\n",ESP.getFlashChipSpeed());
  printf("ESP_IDF_VER:%08x\n", ESP_IDF_VERSION);
  printf("ARDUINO_VER:%08x\n", ESP_ARDUINO_VERSION);
}
void loop(void)
{
  delay(1000);
}

QOUT 40MHz log:

10:09:08.459 -> ets Jun  8 2016 00:22:57
10:09:08.459 -> 
10:09:08.459 -> rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
10:09:08.459 -> configsip: 0, SPIWP:0xee
10:09:08.459 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
10:09:08.459 -> mode:QOUT, clock div:2
10:09:08.459 -> load:0x3fff0030,len:1344
10:09:08.459 -> load:0x40078000,len:13836
10:09:08.459 -> load:0x40080400,len:3608
10:09:08.459 -> entry 0x400805f0
10:09:08.598 -> [⸮2-hal-cpu.c:214] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
10:09:09.623 -> getFlashChipMode : 1
10:09:09.623 -> getFlashChipSize : 4194304
10:09:09.623 -> getFlashChipSpeed : 40000000
10:09:09.623 -> ESP_IDF_VER:00040401
10:09:09.623 -> ARDUINO_VER:00020004

But the result I get with the qio setup is a reboot loop.
(40MHz and 80MHz... The results were the same at both speeds.)

QIO 40MHz log:

10:05:13.154 -> ets Jun  8 2016 00:22:57
10:05:13.154 -> 
10:05:13.154 -> rst:0x10 (RTCWDT_RTC_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
10:05:13.154 -> configsip: 0, SPIWP:0xee
10:05:13.154 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
10:05:13.154 -> mode:QIO, clock div:2
10:05:13.154 -> load:0x3fff0030,len:1344
10:05:13.154 -> load:0xffffffff,len:-1
10:05:13.476 -> ets Jun  8 2016 00:22:57
10:05:13.476 -> 
10:05:13.476 -> rst:0x10 (RTCWDT_RTC_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)

I found a new problem with the QIO settings not working correctly, but at least the logs show mode:QIO and the settings seem to have been reflected.

[lovyan03]

Should I create a new Issue if necessary, since the original topic and content have gone off-topic?

[TD-er]

About the actual used flash mode... This is probably changed by the flashing tool.
You should use the Espressif download tool with the DoNotChangeBin checkbox checked.
The Arduino functions to return flash speed and mode only report what was set at compile time, not the actual mode.
See:

• ESP32 Flash size read via API is wrong when flash is in modes qio, dio, qout #7157
• Get real Flash Chip Size via API call #7159