Speeding up boot time to be comparable with C++ PIO #223
Comments
|
Multiple comments:
I (31) boot: compile time Jun 7 2023 07:48:23
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v1.0
I (41) boot.esp32: SPI Speed : 40MHz
I (45) boot.esp32: SPI Mode : DIO
I (50) boot.esp32: SPI Flash Size : 4MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label Usage Type ST Offset Length
I (71) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (78) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (86) boot: 2 factory factory app 00 00 00010000 003f0000
I (93) boot: End of partition table
I (97) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=11778h ( 71544) map
I (132) esp_image: segment 1: paddr=000217a0 vaddr=3ffb0000 size=02138h ( 8504) load
I (135) esp_image: segment 2: paddr=000238e0 vaddr=40080000 size=0bd6ch ( 48492) load
I (157) esp_image: segment 3: paddr=0002f654 vaddr=00000000 size=009c4h ( 2500)
I (159) esp_image: segment 4: paddr=00030020 vaddr=400d0020 size=3cea0h (249504) map
I (259) boot: Loaded app from partition at offset 0x10000
I (259) boot: Disabling RNG early entropy source...... it seems you are at ~ 260ms BEFORE the bootloader is even giving the control to the Rust app, so whatever you optimize, you should probably start from what the bootloader is doing for so long in the first place. Which has nothing to do with the Rust app itself.
You are just looking at the UART output which is not ideal. For one, the logging via UART itself might be delaying your boot, as it takes time.
The logs you pasted from the PlatformIO boot do not seem to contain the ESP IDF bootloader at all. Are you comparing an ESP IDF application (written in Rust) to another ESP IDF application (written in C/C++) really? With same log levels and all? |
|
Or to put it in another way, where the Rust code actually even starts is after this log line: |
|
I appreciate there are differences in what I'm comparing. I understand that the 402ms mark is where the rust code actually runs, I'm trying to work out how to minimize the time to get to that point in a rust-template application. The logs from PIO I presented are from the main() method for the PIO app. However, I will try and find out if there is a complete system up time value I can log to see if main is actually starting later than I think, to bring the comparison more in line. Regarding your links I did already try adding some of the tweaks we have in sdkconfig.defaults but was unable to get the base 400 value down significantly (best was "calling app_main" starts at 388 instead of 402), with these settings: These are the main settings I pulled across: I tried turning off logging completely with: but it still logs up to "boot: Disabling RNG early entropy source", at 243ms, but then I can't measure when my app has started as there's no logging. I did find some information somewhere about being unable to turn off boot logging completely, so can't gain any benefits there if that is adding overhead. Some other settings from the tweaks page I have tried are also below. This made no difference Neither did this: Adding this in place of POWER_ON version didn't reduce it either: I will continue to investigate the PIO platform too. |
|
I added a log for the esp_timer_get_time() value (device time up in microseconds) which displays it's been up 9.844ms when it logs the line "FujiNet v1.3 2024-04-26 06:08:28 (IEC) Started". However, that appears to be a timer started just before app_main starts according to https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/esp_timer.html, so is missing any activity prior to it being initialised. At most however, I can see a difference of 60ms between pressing reset (the last log is timed as it shuts down) and the startup message of my application, so it is still well below 380-400ms as I'm seeing with a simple template esp-idf application. |
|
What is most important to understand is that - overall - your problem is not a "how to minimize the time to get to that point in a rust-template application" but rather "how to minimize the boot time of ANY ESP-IDF application". So you might have more success if you read the ESP IDF documentation and look what other people have posted on the esp32.com and other ESP IDF related forums because - again - your problem is not specific to the Rust portion at all. With that said, some specific points:
Yes, it IS ESP IDF specific because NO Rust code executes at that point. See above. Yes, it is primarily related to
What happens before the These are the questions which might give you some revelation what is happening.
All configuration options in The bootloader which is built as a side-effect from building the template app is available in
I wouldn't expect these to have any meaningful impact either.
A bootloader option! See above.
BTW: there is NO "PIO platform". PIO is just a build script plus a bunch of other IDE-related utilities.
So for "PIO platform" (your C++ app actually) you could start by investigating what exactly is it using? Arduino? ESP IDF directly? Something weird like NuttX or other 3rd party OS? Is it using the ESP IDF bootloader (99.9% likely, regardless of what lives on top of it). If yes, why you don't see its logs? If this is because the logs for that bootloader are disabled, how about figuring out where is the |
|
We're using PlatformIO, on ESP-IDF: That's why I'm using the esp-idf-template and reported what I'm finding here, as I was trying to get like for like environment built, but instead of c++, using rust.
There aren't any, I've given you the complete log I see on bootup and on reset. I'll look deeper into the bootloader and if there are any options to disable its logging, but as far as I can tell from the esp docs, the value I'm using is minimal:
I'm simply using I don't know if this means the bootloader was flashed or not, and I haven't found any docs that indicate how I can force it with I clearly did find |
================ Don't use Use this instead:
==== Also, since the "PIO platform" app is a stock, boring ESP IDF app after all, your best bet is to look at its own sdkconfig so as to figure out what optimization settings they (the creators of the "PIO platform" app) have applied. To the bootloader and to the main app. Because chances are, you can apply those 1:1 in your "Rust template app" and thus achieve identical boot times. I know I'm repeating myself, but I'm not sure you understood that. If you understood, sorry for the verbosity. |
|
Before I forget: apply |
Which means very likely they've disabled ALL logging in their custom built bootloader plus who knows what else. So (for the third time) - hunt for their sdkconfig*, try to apply their options to your Rust app + bootloader, and you'll likely achieve identical boot times. :) |
|
I was struggling to flash the esptool generated bin file: I've just noticed it says it requires an ELF image, which I've directly used instead of the esptool generated bin file, and it works fine, so I can flash directly from files instead of using cargo, which is useful: However, armed with this knowledge, I tried it via cargo and that produces the same results, there's an entry in the "espflash.toml" file I added to point to the bootloader (you can see it mentioned in the logs) So as you can see, with just the settings I was trying earlier it's down to 160ms to get to app_main now. I'll see what else I can tweak now I know how to get the bootloader flashed. The project I'm heavily involved with (the ones you keep referring to as "they") does include myself, I'm more heavily involved in the software side, but "we" haven't done any extensive changes to the sdkdefaults other than the original ones I posted above that I'm aware of. I'm off to look further on this now I know how to flash the bootloader. I think the key part I was missing was the bootloader not getting flashed by the default "cargo run". I'm not sure all of your comments about not using cargo espflash etc is quite on the ball, but your breakdown of the individual parts was extremely useful to know so I thank you for your insight in that, it's got me to a position I'm happy I could continue dev in rust on esp32 with. I'm extremely happy with that! The target I'm using is esp32s3, but the fujinet project uses the standard esp32, which is why I'm not simply copying the entire sdkconfig.defaults file across, as there are incompatibilities, and the original is generated by platformio for the most part, and I'm trying to grow the new s3 file with values to understand how they affect performance and logging etc. |
|
Just to add, I commented out the line in espidf.rs for the bootloader, and it went back to 400ms doing Then readding the I'm also seeing that adding entries to the sdkconfig.defaults file that affects bootlader now automatically rebuilds and flashes it too. |
(snip)
I've never used
I think we are aligned here? I guess I am - like a broken record - repeating that there is nothing Rust-specific in your task and it is all about ESP IDF bootloader optimization and possibly pre-
Well there is no way for me to know that so I am just trying to be super clear what I mean even at the cost of sounding a bit offensive - sorry for that. with regards to the 160ms that you are still aiming to lower to 40ms - I'm pretty confident it is another option in the bootloader OR in the app startup (pre-
Happy to see your progress and excitement!
I don't think "platformio" is in the "sdkconfig" generation business at all. Either you maintain - manually and carefully - an There is a small chance that you might be hitting something esp32s3 specific w.r.t. startup time though I doubt that. |
|
Since my last post, I've been gradually introducing the sdkconfig defaults values from our project to see what impact each section has and if there's a setting that turns off further startup logging. Some values (particularly around PSRAM) appear to make the s3 fail to boot, which is why I was keen to add them block by block, but it's taking a while. The sdkconfig.defaults file has a big message at the top saying not to edit as it's generated, and if I remove my board specific version from my project and run the pio build, it does get re-generated for me, so I'm pretty sure it's doing something in that area! I'll close this ticket down soon, just thought I'd continue the dialog of my findings until I've completed the config changes.
Understood completely, and I've also been saying that by asking how I can optimise the stuff before the rust code runs. If nothing else, hopefully this will help anyone else trying to find out how to slim down the template app startup, or provide an entertaining read. We live in hope. |
|
It appears our project has turned off all logging below Error, but has a special logger for debug that it uses. I've done similar, set default logging to error, and simply changed log output in my app to print errors to test how fast it gets there. It's down to 40ms, which is superb, proving it can be done. Thanks for your help and information, I didn't react to all your comments, but did read them, and will slowly digest them. |
Motivations
The project I'm involved with have a current ESP32 application written in C++ on PlatformIO that starts up in ~150ms.
For rust, the simple hello_world app is taking 400ms.
The target hosts the devices are connected to are 8 bit machines (atari, c64, coco, etc), and are used as boot drives in some scenarios.
The machines usually come up in ~200ms, so an esp32, powered by the host is already booted and available.
For rust, the 400ms startup would be too long, and immediately makes using it non-starter.
I'm looking for a way to understand if it's possible to have a custom application in rust start up much faster than the hello world template does currently. Not necessarily that the hello world app should start faster, but knowledge on how I can improve startup for an application in rust.
Solution
I want the knowledge/docs to be able to understand and write an application that boots in rust with minimal overhead to try and achieve the same startup times as C++ platformio targets.
Additional context
One area we noticed that speeds up the boot time was which filesystem is used for storage. We switched from SPIFFS to LittleFS and gained several hundred ms, so I'm wondering if there are similar elements to rust startup in template application.
Here is the startup log for the hello world up to the point the application starts
Here's the log from the platformio c++ application:
The text was updated successfully, but these errors were encountered: