Improve boot time

[sslupsky]

@rcolistete @jcaron Thank you for the feedback. I overlooked that micropython needs to load the modules each time. That likely explains the long boot time.

The cycle time of the code segment below measured from Wake to Wake is about 14.5 - 15 seconds when I disable the debug (print's, blinks and pause). The sleep time is 10 seconds.

Here is the code I am using for the test.

boot.py

from network import Bluetooth
import pycom


if pycom.heartbeat() == True:
    pycom.heartbeat(False)

if pycom.wifi_on_boot() == True:
  pycom.wifi_on_boot(False)

bluetooth = Bluetooth()
bluetooth.deinit()

main.py

from network import LoRa
from network import Bluetooth
import socket
import pycom
import time
import ubinascii
import config
import struct
from machine import ADC
import machine


def hello():
  debug_print("debug", "Hello")
  blink(2, 0x00FF00)
  return

def select_subband(lora, subband):
  if (type(subband) is int):
    if ((subband<1) or (subband>8)):
      raise ValueError("[LoRa] subband out of range (1-8)")
  else:
    raise TypeError("[LoRa] subband must be 1-8")

  for channel in range(0, 72):
    lora.remove_channel(channel)

  for channel in range((subband-1)*8, ((subband-1)*8)+8):
    lora.add_channel(channel, frequency=902300000+channel*200000, dr_min=0, dr_max=3)

  lora.add_channel(63+subband, frequency=903000000+((subband-1)*1600000), dr_min=4, dr_max=4)
  return

def blink( num=1, color=0x0000FF ):
  if DEBUG_LED:
    for n in range(0, num):
      pycom.rgbled(color)
      time.sleep(0.2)
      pycom.rgbled(0x000000)
      time.sleep(0.2)
  return

def debug_print( type, msg ):
  if DEBUG_PRINT:
    print( "[", type, "] ", msg)
    time.sleep(0.2)
  return

LORA_SUBBAND = const(1)
LORA_NODE_DR = const(3)
SLEEP_TIME = const(10)
DEBUG_PRINT = True
DEBUG_LED = True
DEBUG_PAUSE = False

# Initialize ADC
esp32adc = ADC(0)

# Initialise LoRa in LORAWAN mode.
lora = LoRa(mode=LoRa.LORAWAN, region=LoRa.US915)

resetCause = machine.reset_cause()
wakeReason = machine.wake_reason()

hello()

# reset and wake reasons
# https://docs.pycom.io/firmwareapi/pycom/machine
debug_print("machine", "Reset cause: " + str(resetCause))
debug_print("machine", "Deep sleep wakeup reason: " + str(wakeReason))
debug_print("machine", "Approximate deep sleep time remaining: " + str(machine.remaining_sleep_time()) + " millisec")

if resetCause == machine.PWRON_RESET:
  pass
elif resetCause == machine.WDT_RESET:
  pass
elif resetCause == machine.DEEPSLEEP_RESET:
  pass
else:
  pass
  
if wakeReason[0] == machine.PWRON_WAKE:
  # should the LoRa context be reset here?  ie:  lora.nvram_erase() ?
  pass
elif wakeReason[0] == machine.RTC_WAKE:
  # restore LoRa context if wake from sleep
  debug_print("LoRa", "Restoring LoRa context ...")
  lora.nvram_restore()
else:
  pass


# configure ADC
esp32adc_c = esp32adc.channel(pin='P13')

# configure LoRa
select_subband(lora, LORA_SUBBAND)
dev_eui = lora.mac()
debug_print("LoRa", "dev_eui = " + ubinascii.hexlify(dev_eui).upper().decode('utf-8'))

# create an OTAA authentication parameters
app_eui = ubinascii.unhexlify('redacted')
app_key = ubinascii.unhexlify('redacted')

joinAttempts = 0
if not lora.has_joined():
  # wait until the module has joined the network
  while not lora.has_joined() and joinAttempts < 10:
    # join a network using OTAA (Over the Air Activation)
    lora.join(activation=LoRa.OTAA, auth=(dev_eui, app_eui, app_key), timeout=0)
    time.sleep(2.5)
    if lora.has_joined():
      debug_print("LoRa", "Successfully joined LoRa network")
      blink(2, 0x0000FF)
    else:
      debug_print("LoRa", "LoRa network not yet joined...")
      joinAttempts += 1
  if not lora.has_joined() and joinAttempts >= 10:
    debug_print("LoRa", "Failed to join LoRa network")
else:
  debug_print("LoRa", "In LoRa network")
  blink(1, 0x0000FF)

if lora.has_joined():
  # create a LoRa socket
  s = socket.socket(socket.AF_LORA, socket.SOCK_RAW)

  # set the LoRaWAN data rate
  s.setsockopt(socket.SOL_LORA, socket.SO_DR, LORA_NODE_DR)

  # make the socket blocking
  # (waits for the data to be sent and for the 2 receive windows to expire)
  s.setblocking(True)

  # send some data
  value = esp32adc_c.value()
  debug_print("adc", "value: " + str(value))
  payload = value.to_bytes(2, "little")
  s.send(payload)

  # make the socket non-blocking
  # (because if there's no data received it will block forever...)
  s.setblocking(False)

  # get any data received (if any...)
  data = s.recv(64)
  debug_print("debug", data)

# wait after wake
blink(1, 0xFF0000)
debug_print("debug", "Press CTRL-F to soft reset and drop back to RLE")
if DEBUG_PAUSE:
  time.sleep(SLEEP_TIME)

debug_print("debug", "Done")

# Prepare LoRa to sleep
if lora.has_joined():
  lora.nvram_save()

debug_print("debug", "Going to sleep for " + str(SLEEP_TIME) + " seconds ...")
blink(3, 0x00FF00)

# deep sleep
machine.deepsleep(SLEEP_TIME * 1000)

[robert-hh]

@sslupsky Loading modules is much faster if the are pre-compiled with mpy-cross. But you cannot do that with main.py. So you have to put the bulk of you code into a different script, and in main.py you simply import that. Since your script is not very long, the overall boot time improvement is not that good.

[jcaron]

@sslupsky See my answer in the other thread.

Your 14-15 seconds include:

• 10 seconds deep sleep
• boot time
• LoRaWAN send time (not much, you're at SF7, so less than 100 ms)
• RX1 and RX2 (at least 2 seconds, possibly more if the network sends a higher RX delay)
• possibly receive time

Your boot time is thus at most 3 seconds, not 4.5...

Why are you touching Bluetooth? IIRC there's no need to.

[crumble]

@sslupsky

Switch off your debug_print. Sending the text over the serial needs time. Addtional there is an unecessary sleep after the prrint.

[sslupsky]

@jcaron Somewhere here I recall someone said to disable bluetooth to minimize power. I updated my code to remove the Bluetooth and that shaved about 0.4 sec from the boot it seems.

I added a timer that starts at the beginning of main and stops at the end just before the sleep. I timed the loop with the debug on which was 18.6 sec. The timer reported 6.6 sec in main. Using these figures it appears the boot time is 18.6 - 6.6 - 10 = 2.0 sec. There is about 0.4 sec delay so factoring that indicates boot time is about 1.6 sec.

Thanks for the feedback.

[jcaron]

@sslupsky 3 seconds still seems to be a bit long, but I have no experience with the LoPy 4, only the original LoPy.

Also, check the firmware release announcement threads, I believe someone mentioned one of the versions increasing boot time, not sure if that was fixed since then (and/or if that was in the stable or dev versions). Which firmware version are you running BTW?

[robert-hh]

@jcaron I tested the boot time on a LoPy4 and a LoPy1 as the time between the rising edge of Reset and a Pin pulse cause by a few lines in boot.py. This time is 1.97 seconds. From then on, control is by the user scripts.

[Sympatron]

@robert-hh said in Improve boot time:

@jcaron I tested the boot time on a LoPy4 and a LoPy1 as the time between the rising edge of Reset and a Pin pulse cause by a few lines in boot.py. This time is 1.97 seconds. From then on, control is by the user scripts.

Does that mean that ~2s is the absolute minimum boot time or do you know of any why to speed it up it further?
Is the boot time for LoPy1 and 4 the same?

[robert-hh]

@sympatron As far as I can tell, this is the minimum boot time, unless you start to tweak the firmware. And to my surprise, lopy1 and lopy4 are the same. I should say, that the firmware version is 1.18.1.r1.

[danielm]

This is the thread where I described the issue with boot time being longer for FW 1.18.0 in comparison to FW 1.14.0.b1 while running the same code:
https://forum.pycom.io/topic/3377/fw-1-18-0-increased-boot-time-power-consumption

I did not perform tests with development FW 1.19.0 yet and the source of the issue remains unclear.

[jcaron]

@danielm Thanks.

There was indeed a 300 ms increase in boot time between the two, but the total boot time remained under a second.

I wonder how long it actually takes to load and compile a relatively simple script such as OP's, and how long it takes for the various imports.

[robert-hh]

@jcaron Just for completion other boot times:

• WIPy3 (clone): ~1.8 s.
• FiPy: ~1.95 s

So it#s all in the same range.

[jcaron]

@robert-hh Can you reproduce @danielm 's second test in that thread? I'm surprised he got about 500 or 800 ms depending on the firmware version and you get nearly 2 seconds. Unless you're importing some module that really takes a long time to load, but he already had imports of machine, pycom and os.

@danielm What device where you using in those tests? I guess a LoPy or LoPy 4?

[robert-hh]

@jcaron The only import I had is machine for the Pin to signal the presence of boot. And obviously the stuff from _boot.py:

# _boot.py -- always run on boot-up, even during safe boot
import os
from machine import UART
os.dupterm(UART(0, 115200))

I removed that and got 1.77 seconds.
Now, with these line, the LoPy4 shows 1.87 seconds. But after all, not a big variation.

[danielm]

@jcaron
I think it was L01 because the application from the first post in that thread was written for sensor based on L01.

In all tests the application was frozen during firmware build time.

[robert-hh]

@jcaron With version 1.14.0.b1 I get 1.6 seconds.