ESP32S3 Boot Very Slow with Large codebase

[linfan68]

I am currently working on porting an existing JS code base into ESP32 using Moddable. The code base is in TypeScript and was originally running on a NodeJS server. I spent two days refactoring the code to make it "platform plug-able" and now the same code is running on both NodeJS and ESP32!!!

However I found the boot time suddenly becomes unacceptable slow, here is the boot log:

I (0) cpu_start: App cpu up.
...
/// More ESP bootloader log...
...
instruments key: Pixels drawn,Frames drawn,Network bytes read,Network bytes written,Network sockets,Timers,Files,Poco display list used,Piu command List used,SPI flash erases,Turns,System bytes free,CPU 0,CPU 1,Chunk used,Chunk available,Slot used,Slot available,Stack used,Stack available,Garbage collections,Keys used,Modules loaded,Parser used,Floating Point
No Wi-Fi SSID
// !!!! 20+ SECONDS HERE !!!!
************************************  // <=== THIS IS FIRST LINE OF OUR JS CODE
************************************
  
instruments: 0,0,0,0,0,0,0,0,0,0,0,1515082,0,100,96308,97024,629712,631184,7056,163840,389,186,1,0,128
[     Drv] >>> init
[     Drv] <<< init
[     Mod] >>> init
[ SrvConn]   >>> init
[ SrvConn]   <<< init
[     Mod] <<< init
instruments: 0,0,0,0,0,2,0,0,0,0,0,1513630,0,100,97120,98304,630928,631184,2992,163840,5,186,0,0,6
instruments: 0,0,0,0,0,2,0,0,0,0,0,1513630,0,0,97120,98304,630928,631184,208,163840,0,186,0,0,0

After logging "No Wi-Fi SSID", there is a delay of approximately 20 seconds before the first line of the application is executed. Through experimentation, it appears that this delay is closely related to the amount of code imported and used by the program. However, it is uncertain whether this delay is related to the specific files being imported or the functions being utilized.

And yes, we have approximately 10,000 lines of auto-generated TypeScript code that manages communication protocols. I've noticed that the size of the image remains unchanged even when I add or remove references to the large file (which is around 2MB in size).

Writing at 0x00205c45... (94 %)
Writing at 0x0020dbd5... (96 %)
Writing at 0x00213490... (98 %)
Writing at 0x00218e10... (100 %)
Wrote 2140576 bytes (889258 compressed) at 0x00010000 in 19.0 seconds (effective 899.1 kbit/s)...

ased on my understanding of the XS engine, having a large code base should not be an issue since the byte-code is stored and executed in ROM. In fact, according to the documentation:
Since everything is ready in ROM, your application boots instantaneously.

I would greatly appreciate it if someone could kindly point out anything that I may have overlooked.

[phoddie]

Good morning!

Congratulations on getting such a large code base shared between the two environments. It isn't 100% obvious what might be causing the slow down here. Let's try to figure it out.

The delay is after the virtual machine is instantiated. We know that because the "No Wi-Fi SSID" message is logged by setup code that is implemented in JavaScript. That helps to limit where we need to look.

...based on my understanding of the XS engine, having a large code base should not be an issue since the byte-code is stored and executed in ROM. In fact, according to the documentation:

Since everything is ready in ROM, your application boots instantaneously.

This sentence is preceded by a discussion of preloading by the XS linker: "The XS linker constructs all built-ins and preloads most modules..."

Preloading

If your modules are not being preloaded, they will still take some time to instantiate. That time is less than compiling the source code to byte code (the byte code is already stored in ROM) but can still add-up. xsbug is a great way to check which modules are preloaded. Set a breakpoint at the start of your main.js. In xsbug, look at the "modules" panel. The modules that are preloaded are displayed in blue, those which are not preloaded are displayed in black. Here you can see that here helloworld all the Moddable SDK modules (time, timer, Resource, etc) are preloaded and only main.js is not:

The preload documentation describes in detail how to preload modules. Not every module can be preloaded, but most can be (nearly all modules in the module SDK are).

Profiling

The profiler is a useful tool for understanding where time is being spent. There's an introduction to the profiler on our blog and more detailed profiler documentation on the implementation and interpreting the results.

You can start/stop the profiler dynamically through the UI. There is also an option to start profiling when the VM is created. In this case, that might be your best choice. That's controlled in xsbug preferences:

Let's see what you find by investigating preload and profiling. We can continue the investigation from there.

[linfan68]

The preload thing sounds right. Those generated protocol parsing modules has thousands of small functions... the RAM cost should be fine for me (my board has PSRAM), but I can imagine that scanning and importing that module will require a significant amount of processing time.
I'll give it a try tonight.

[linfan68]

Preload is the answer!!!
By including the XXXL module in the "preload" fields of the manifest.json file, the startup time was reduced to zero!
Thank you, @phoddie, for your prompt and thorough response. Your dedication to maintaining this wonderful project and community is truly appreciated.

[phoddie]

Excellent. I'm glad it was that easy!