Slow SPI communication on ESP32 at 10Mhz CPU speed

[devRomeos]

I have an ESP32 underclocked to 10mhz, I realise that simply sending 1 byte takes 40mS

For science I have tried at 20Mhz where it takes just half as long (20mS) and at 40Mhz also half as long, 10mS which is already an acceptable figure but unfortunately I need to keep the CPU clock at 10Mhz for power reasons.

It's probably not the fault of this library at all, but I would like to know where so much time may be wasted or hopefully how to improve this.

#include <Arduino.h>
#include <RadioLib.h>
#include <SPI.h>

#define RADIO_FREQUENCY 866.3
#define RADIO_BANDWIDTH 500
#define RADIO_SPREADING_FACTOR 5
#define RADIO_CODING_RATE 7
#define RADIO_SYNC_WORD RADIOLIB_SX126X_SYNC_WORD_PRIVATE
#define RADIO_OUTPUT_POWER 10
#define RADIO_PREAMBLE_LENGTH 8
#define RADIO_TXCO 0
#define RADIO_DCDC true

#define PIN_CS 5
#define PIN_BUSY 33
#define PIN_DIO1 25
#define PIN_NRESET 26

SPISettings spiSettings(1000000, MSBFIRST, SPI_MODE0); // didn't improve with more than 1MHz

SX1262 radio = new Module(PIN_CS, PIN_DIO1, PIN_NRESET, PIN_BUSY, SPI, spiSettings); // RA-01SH

void setup()
{

  setCpuFrequencyMhz(10);
  Serial.begin(115200);

  SPI.begin();

  int state = radio.begin(RADIO_FREQUENCY, RADIO_BANDWIDTH, RADIO_SPREADING_FACTOR,
                          RADIO_CODING_RATE, RADIO_SYNC_WORD, RADIO_OUTPUT_POWER,
                          RADIO_PREAMBLE_LENGTH, RADIO_TXCO, RADIO_DCDC);

  radio.setCRC(2);
}

void loop()
{

  unsigned long startTime, endTime;

  startTime = micros();
  radio.transmit("1", 1);
  endTime = micros();
  Serial.printf("Time to sent: %.2f ms\n", (endTime - startTime) / 1000.0); // ~38ms

  delay(5000);
}

[jgromes]

I realise that simply sending 1 byte takes 40mS

Sending 1 byte is no simpler than sending 200, the only difference is the length of the packet. All configuration of the radio still must take place.

You can enable the SPI debug level to see how many SPI transactions there are. It will skew the timing benchmark because debug takes place over Serial, but it will at least show the amount of transactions and when they happen. I would also verify what is the actual SPI clock speed when the ESP32 at 10 MHz.

[devRomeos]

Thanks for you tips

EDIT: Interrupt and busy cables were loose so the time spent has improved, but is still high. 27mS

I was meaning with sending a single byte that there is not a significant time spent on air and those 40 ms are likely just SPI transitions ( assuming that the airtime is measured here )

I tested the SPI debug and as you said, the serial print induces delay and it is not possible to get anything clear, here is the log in any case

13:18:05.603 > RLB_SPI: CMDW    80
13:18:05.603 > RLB_SPI: SI              0
13:18:05.603 > RLB_SPI: SO      A2      A2
13:18:05.603 > RLB_SPI: CMDR    11
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      1
13:18:05.603 > RLB_SPI: CMDR    11
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      1
13:18:05.603 > RLB_SPI: CMDR    1D      7       36
13:18:05.603 > RLB_SPI: SI                              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2      D
13:18:05.603 > RLB_SPI: CMDR    C0
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      22      22
13:18:05.603 > RLB_SPI: CMDW    D       7       36
13:18:05.603 > RLB_SPI: SI                              D
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    8C
13:18:05.603 > RLB_SPI: SI              0       8       0       1       1       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    8
13:18:05.603 > RLB_SPI: SI              2       1       0       1       0       0       0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2      A2      A2      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    8F
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    E       0
13:18:05.603 > RLB_SPI: SI                      31
13:18:05.603 > RLB_SPI: SO      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    2
13:18:05.603 > RLB_SPI: SI              43      FF
13:18:05.603 > RLB_SPI: SO      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDR    1D      8       89
13:18:05.603 > RLB_SPI: SI                              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2      0
13:18:05.603 > RLB_SPI: CMDR    C0
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      22      22
13:18:05.603 > RLB_SPI: CMDR    11
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      1
13:18:05.603 > RLB_SPI: CMDW    D       8       89
13:18:05.603 > RLB_SPI: SI                              0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDW    83
13:18:05.603 > RLB_SPI: SI              0       0       0
13:18:05.603 > RLB_SPI: SO      A2      A2      A2      A2
13:18:05.603 > RLB_SPI: CMDR    11
13:18:05.603 > RLB_SPI: SI              0       0
13:18:05.603 > RLB_SPI: SO      AC      AC      1
13:18:05.603 > RLB_SPI: CMDW    2
13:18:05.603 > RLB_SPI: SI              43      FF
13:18:05.603 > RLB_SPI: SO      AC      AC      AC
13:18:05.603 > RLB_SPI: CMDW    80
13:18:05.603 > RLB_SPI: SI              0
13:18:05.603 > RLB_SPI: SO      AC      AC
13:18:05.603 > Time to sent: 229.52 ms

With my limited knowledge I have connected a scope and it seems to work up to 2 Mhz fine. In my opinion, SPI speed does not seem to be a problem for this small amount of data, I have made a small table.

CPU Speed	SPI Speed	Bytes sent	Time
10 Mhz	100Khz	8	29.98mS
10 Mhz	500Khz	8	27.35mS
40 Mhz	500Khz	8	9.73mS
240 Mhz	500Khz	8	6.01mS
10 Mhz	1Mhz	8	27.11mS
40 Mhz	1Mhz	8	9.11mS
240 Mhz	1Mhz	8	5.30mS

I have added a GPIO by holding it HIGH until the end of the transmission and the time matches the calculation of micros().

I see that there is a long period of no communication until there is a final short communication and everything ends?
<- Solved, Interrupt and busy cables were loose.

MISO/MOSI transfers seems good and fast. but seems to be a considerable delay (~1mS) between all of them and where this huge delay is coming from. Could be some kind of timeout that is being affected by the CPU frequency?

[jgromes]

MISO/MOSI transfers seems good and fast. but seems to be a considerable delay (~1mS) between all of them

There are some large delays (50 ms) in the SPI transaction methods if the BUSY pin is not used, but that doesn't seem to be your case. I would suggest checking that pin with the oscilloscope since it will tell us directly how much time is spent waiting for the SX126x device. There is also a small (1us) delay applied always (see below), so it is possible at low CPU frequency the ESP32 is not measuring this delay correctly.

RadioLib/src/Module.cpp

Lines 377 to 383 in 2ca2ddf

	if(waitForGpio) {
	if(this->gpioPin == RADIOLIB_NC) {
	this->hal->delay(1);
	} else {
	this->hal->delayMicroseconds(1);
	RadioLibTime_t start = this->hal->millis();
	while(this->hal->digitalRead(this->gpioPin)) {

[StevenCellist]

10mhz, I realise that simply sending 1 byte takes 40mS

Forgive me if I'm wrong, but 10MHz is 10e6, so a single clock cycle is 10e-6 or 1us (microsecond), which to me would look like a byte should also take in the order of microseconds - how would you end up with 1 byte taking 40ms?

[HeadBoffin]

I concur, 40ms is like forever ...

[devRomeos]

I agree that 40ms for such a small sum (including SPI transactions) is like forever and even more.