Module freezing for Pycom MicroPython

[Andreas]

Hier geht es um das Einfrieren von generischen Python Modulen für den effizienteren Betrieb unter MicroPython.

[Andreas]

Introducing external frozen modules

Wir bereiten gerade die ahead-of-time Bytecode-Kompilierung von .py-Dateien in .mpy-Dateien per mpy-cross vor, also die Erstellung von frozen modules ^[1]. Wir versprechen uns davon Effizienzzugewinne bei der Dateiübertragung und zur Laufzeit ^[2]. Dafür wäre es fein, wenn wir gemeinsam prüfen, ob das auf allen bei uns verwendeten Betriebssystemen gut klappt.

Der Einstieg wäre ungefähr folgender threeliner. Bei mir auf macOS geht das gut, während man unter Linux – naja… – kurz nachhelfen muss ^[3].

# Virtualenv benutzen, um System nicht zu verschmutzen
virtualenv --python=python2 .venv2
source .venv2/bin/activate

# pip auf den aktuellen Stand bringen
pip install pip --upgrade

# mpy-cross für MicroPython 1.9.4 plattformneutral installieren
pip install mpy-cross==1.9.4

# Permission-Probleme unter Linux beheben
chmod +x "$(dirname $(python -c 'import mpy_cross; print(mpy_cross.__file__)'))/mpy-cross"

# Run pre-flight checks
python -m mpy_cross
no input file

Wenn das auf allen gewünschten Plattformen (Linux, macOS, Windows) gut klappt, müssen wir im weiteren Verlauf keine krummen Sonderwege einbauen. Daher will ich hiermit kurz vorfühlen und freue mich über Eure Berichte.

Während mpy-cross für MicroPython 1.11 bereits gut unter Python3 installiert, sind wir für die Installation von mpy-cross für MicroPython 1.9.4 noch auf Python2 angewiesen. Das wiederum brauchen wir, weil das Pycom MicroPython weiterhin auf MicroPython 1.9.4 basiert – siehe MicroPython quo vadis.

Viele Grüße,
Andreas.

---

1. • mpy-cross · PyPI
   • Adding Frozen Modules | Building CircuitPython | Adafruit Learning System
   • Frozen Modules | MicroPython Basics: Loading Modules | Adafruit Learning System
   • Frozen Modules | MicroPython for SAMD21 | Adafruit Learning System
   ↩︎

2. 30 sec boot time vs deep sleep | Pycom user forum ↩︎

3. Invoking mpy_cross.run() gives "Permission denied" on Linux (#3) · Issues · alelec / mpy_cross · GitLab ↩︎

[Andreas]

libero läuft nun wieder als Testgerät für die letzten Änderungen und ist wieder auf dem Programm Teststände / [amo] FiPy Testbench Power zu sehen.

Bisher sahen wir durch die ahead-of-time Kompilierung per mpy-cross keine der erwarteten Effizienzsteigerungen zur Laufzeit. Die Übertragung auf das Gerät geht jedoch geringfügig flotter und nach unserem Gefühl auch wesentlich stabiler über die Bühne – es gibt nun keine der beobachteten 500/550er Fehler bei der Übertragung per FTP mehr.

Der Unterschied in der Datenmenge ist nicht insignifikant, er beträgt knapp die Hälfte gegenüber der nicht-kompilierten Variante.

$ du -sch dist-packages terkin hiveeyes lib
612K	total

$ du -sch lib-mpy/
372K	total

[clemens]

@Andreas

Bisher sahen wir durch die ahead-of-time Kompilierung per mpy-cross keine der erwarteten Effizienzsteigerungen zur Laufzeit.

Startup ist auch nicht schneller?? Bei mir braucht er gerade nach einem Aufwachen aus dem deep sleep oder reset 17 Sekunden bis die erste log-message kommt. Ist das der erste Punkt wo nach dem Kompilieren was passiert oder müsste man von den 17 Sekunden noch Zeit abziehen?

Initializing filesystem as LittleFS!
   16.9251 [terkin.configuration     ] INFO   : Starting TerkinConfiguration on path "/flash"

Oben hast du ja auch auf 30 sec boot time vs deep sleep | Pycom user forum verlinkt. Dort vermuten die meisten ja, dass es mit pro-compiling ggf. nicht getan ist, sondern das Problem wo anders liegen könnte:

as 30 seconds really is abnormally long

Eine Vermutung:

it’s likely not just loading, but also a lot of code execution performed.

Der thread-Ersteller meint dann aber:

Pretty sure. I measured before and after the imports in boot.py and main.py and that’s where the time is going. The imports themselves don’t “do” anything but declare classes and functions. There’s very little to no processing going on.

Ein anderer hat schon kapituliert:

My own code is too large to deep sleep,

Letzte Vermutung:

Sounds like you wait a lot for the network inits and other stuff.

Kann es sein, dass die Zeit gar nicht fürs kompilieren, sondern für andere Dinge gebraucht wird?

[Andreas]

R A N T

TLDR; Hab gestern schon an den Kuhzaun g’langt. Hat’s mir sauber eine g’wischt. Müssen andere ja nicht nachmachen.

Kontext: Freezing modules

https://community.hiveeyes.org/t/kontinuierliche-verbesserungen-des-terkin-datenloggers-600er/2121/104

Einleitung

Gestern habe ich die Buildumgebung für Pycom-MPY-Firmwares pycom-docker-fw-build bei uns per Add tools for building firmware images for ESP32 based on Pycom Micro… · hiveeyes/terkin-datalogger@74c2415 · GitHub eingebaut und wollte in den letzten Zuckungen noch ne komplette Firmware draus gießen, damit wir endlich OTA-Rodeo reiten können.

Da gibts aber noch Notizen dazu:

Note

The Frozen code implementation might not support sub-directories in MicroPython code.

– pycom-libraries/pycom-docker-fw-build at master · pycom/pycom-libraries · GitHub

Jetzt aber

MIGHT NOT SUPPORT SUB-DIRECTORIES

This effectively means: “Never heard of Python module namespaces” anyway.

This is abs… fu… craz… ridiculous!

– Why does this always happen to me.

[Andreas]

@Andreas

MIGHT NOT SUPPORT SUB-DIRECTORIES

Maybe GitHub - Akrog/pinliner: Python Inliner merges in a single file all files from a Python package. will come to the rescue here.

[Andreas]

@Andreas

Bisher sahen wir durch die ahead-of-time Kompilierung per mpy-cross auf dem Pycom FiPy keine der erwarteten Effizienzsteigerungen zur Laufzeit.

Während der Pycom Fipy mit MicroPython 1.9.4 weiterhin zwischen 9 und 12 Sekunden lange braucht, um die Module der Firmware zu laden…

Initializing filesystem as LittleFS!
[boot.py] INFO: Python module search path is: ['', '/flash', '/flash/lib']
[boot.py] INFO: Starting "umal" bootloader
[umal]     INFO: Python module search path is: ['/flash/lib-mpy', '', '/flash', '/flash/lib', '/flash/dist-packages', '/flash/terkin', '/flash/hiveeyes']
[main.py] INFO: Loading settings
[main.py] INFO: Starting logging
[main.py] INFO: Starting Terkin Datalogger
[main.py] INFO: Loading modules
   12.3554 [terkin.configuration     ] INFO   : Starting TerkinConfiguration on path "/flash"

… wissen wir nun, dass es auch schneller über die Bühne gehen kann. Auf einem aktuellen pyboard-D PYBD-SF2-W4F2 mit MicroPython 1.10 vom 29. Mai 2019 läuft der Datenlogger bereits nach einer guten Sekunde los.

[boot.py] INFO: Python module search path is: ['', '/flash', '/flash/lib']
[boot.py] INFO: Starting "umal" bootloader
[umal]     INFO: Python module search path is: ['/flash/lib-mpy', '', '/flash', '/flash/lib', '/flash/dist-packages', '/flash/terkin', '/flash/hiveeyes']
[main.py] INFO: Loading settings
[main.py] INFO: Starting logging
[main.py] INFO: Starting Terkin Datalogger
[main.py] INFO: Loading modules
    1.1010 [terkin.configuration     ] INFO   : Starting TerkinConfiguration on path "/flash"

Der ESP32 auf dem FiPy läuft mit 160 MHz, während die Cortex M7 CPU auf dem pyboard-D mit 216 MHz läuft. Unabhängig davon wurde aber auch das .mpy Dateiformat beim moderneren MicroPython verbessert. Es zeigte sich, dass auf dem pyboard im Auslieferungszustand

MicroPython v1.10-445-ga9b1d3ca3 on 2019-05-29; PYBD_SF2W with STM32F722IEK

bereits – ausschließlich – das neuere mpy file format v4 unterstützt.

./bin/mpy-cross/1.11/mpy_cross/mpy-cross --version
MicroPython v1.11-dirty on 2019-06-01; mpy-cross emitting mpy v4

Starting with release 1.11, the mpy file format has been moved to version 4 and has some significant improvements: mpy file size is reduced on average by about 35%, loading time of mpy files is reduced by about 40%, and they now have support to save native, viper and inline assembler code (or machine code generated from any other source). Size reduction of mpy files was achieved by adding a qstr window to reuse past qstrs when encoding them, by packing qstrs directly in the bytecode, and by defining a static qstr set.

– Release Improved mpy format with support for native code, and new JavaScript port · micropython/micropython · GitHub

[clemens]

Liegt es denn tatsächlich an der anderen Hardware / dem anderen filesystem oder wird nur weniger, nicht unterstütztes eingebunden und das System ist daher schneller, s. z.B.

@poesel

Terkin/device:

    if sys.platform in ['WiPy', 'LoPy', 'GPy', 'FiPy']:
        import pycom

[Andreas]

@clemens

Liegt es denn tatsächlich an der anderen Hardware / dem anderen filesystem

Nein, ich vermute es liegt vor allem an der Effizienzsteigerung im Vergleich zwischen MicroPython 1.9.4 und MicroPython 1.10. Die zusätzlichen MHz machen bestimmt noch ein weiteres Quäntchen aus, vielleicht aber auch unabhängig von der Taktfrequenz ein generell schnellerer Zugriff auf das RAM.

[Andreas]

@Damien George

Starting with release 1.11, the mpy file format has some significant improvements: mpy file size is reduced on average by about 35%, loading time of mpy files is reduced by about 40%.

– Release Improved mpy format with support for native code, and new JavaScript port · micropython/micropython · GitHub

Dank dem Pycom Firmware Release 1.20.1 kommen wir nun auch endlich in den Genuß dieser Optimierungen.

Die Datenlogger-Software lädt nun in 5(!) Sekunden.

Pycom MicroPython 1.20.1.r1 [d4b4717] on 2019-10-12; FiPy with ESP32

[boot.py] INFO: Python module search path is: ['', '/flash', '/flash/lib']
[boot.py] INFO: Starting "umal" bootloader
[umal]     INFO: Python module search path is: ['/flash/lib-mpy-1.11-pycom', '', '/flash', '/flash/lib', '/flash/dist-packages', '/flash/terkin', '/flash/hiveeyes']
[main.py] INFO: Loading settings
[main.py] INFO: Starting logging
[main.py] INFO: Loading Terkin Datalogger
[main.py] INFO: Loading modules
    5.3854 [terkin.datalogger        ] INFO   : Starting Terkin datalogger
[...]

und nach knapp 30 Sekunden ist der erste Zyklus beendet ^[1].

[...]
   26.1058 [terkin.telemetry         ] INFO   : Connecting to MQTT broker at ('46.4.251.66', 1883) succeeded
   26.2219 [terkin.datalogger        ] INFO   : Telemetry status: SUCCESS (1/1)
   26.5048 [terkin.device            ] INFO   : Start curating the garbage collector
   26.8175 [terkin.device            ] INFO   : Curating the garbage collector finished. Free memory: 2334240
   26.9451 [terkin.datalogger        ] INFO   : Device is in maintenance mode. Skipping deep sleep and adjusting interval to 8.342 seconds
   26.9688 [terkin.device            ] INFO   : Waiting for 8.342 seconds

---

Unsere Schritte waren (skizzenhaft):

make setup
make list-serials
export MCU_PORT=/dev/cu.usbmodemPy001711 # libero
make erase-device
make install-pycom-firmware pycom_firmware_file=FiPy-1.20.1.r1-robert.tar.gz

make terkin-agent action=monitor macs=80:7d:3a:c2:de:44 # libero
make connect-wifi ssid=GartenNetzwerk password=<redacted>
make recycle-ng MPY_CROSS=true MPY_TARGET=pycom MPY_VERSION=1.11

---

1. In diesem Fall ist zu beachten, dass keinerlei Sensoren angeschlossen sind. In der Praxis dauert es also noch ein paar Sekunden länger. ↩︎

[clemens]

Quantensprung! Absolut super die Hochfahrzeit! Vielen Dank fürs Researchen @Andreas!!

[Andreas]

Annapurna Firmware for Pycom/ESP32

@clemens

Quantensprung!

In the spirit of Running the Terkin-Datalogger on STM32, we just made a release tarball containing all the relevant baseline libraries ^[1]. It is a complete firmware image based on the most recent Pycom Firmware Release 1.20.1.

While you won’t be able to use this guy for hacking on the software, it definitively takes some pain out of operating it. Just add some sugar ^[2]. Enjoy!

Before flashing this to your device, you might want to erase it completely in order to prevent any collisions between frozen and non-frozen modules and to prevent other weird obstacles when upgrading from the vanilla Pycom firmware ^[3].

---

1. https://packages.hiveeyes.org/hiveeyes/foss/pycom/FiPy-1.20.1.r1-annapurna-0.2.0.tar.gz ↩︎

2. Which is boot.py, main.py and settings.py. ↩︎

3. Installing the recent Pycom Firmware 1.20.1.r1 requires erasing the flash memory completely ↩︎

[Andreas]

@Andreas

Die Datenlogger-Software lädt nun in 5(!) Sekunden.

Besides making the provisioning process way more convenient, it also improves runtime efficiency slightly.

 3.8909 [terkin.datalogger        ] INFO   : Starting Terkin datalogger

...

22.0135 [terkin.datalogger        ] INFO   : Telemetry status: SUCCESS (1/1)

[Andreas]

Coming from here, we started building Annapurna firmware for Pycom/ESP32, which will include almost all files of the Terkin Datalogger within the firmware image.