From 7185b9c603f159fc8c06d26625b56d9f16d14558 Mon Sep 17 00:00:00 2001 From: Philip Gladstone Date: Sun, 18 Oct 2020 14:46:47 -0400 Subject: [PATCH] Improved startup performance and measurement tools. (#3171) * Don't adjust the clock until after we deal with rtctime... * Switched to using START_OPTION_CPU_FREQ_MAX instead. * Use setfield and add caching of the startup option * Put the startupcounts warning into a warning box --- app/include/user_config.h | 5 ++ app/lua53/lua.c | 9 ++- app/modules/file.c | 24 +++++--- app/modules/node.c | 119 +++++++++++++++++++++++++++++++++++- app/platform/platform.c | 14 +++++ app/platform/platform.h | 31 ++++++++++ app/spiffs/nodemcu_spiffs.h | 2 + app/spiffs/spiffs.c | 13 ++++ app/user/user_main.c | 18 +++++- docs/modules/node.md | 77 ++++++++++++++++++++++- 10 files changed, 299 insertions(+), 13 deletions(-) diff --git a/app/include/user_config.h b/app/include/user_config.h index 27b9d08a..2063b7e4 100644 --- a/app/include/user_config.h +++ b/app/include/user_config.h @@ -249,6 +249,11 @@ #endif //#define SPIFFS_SIZE_1M_BOUNDARY +// The following define enables recording of the number of CPU cycles at certain +// points in the startup process. It can be used to see where the time is being +// consumed. It enables a nice node.startupcounts() function to get the results. +//#define PLATFORM_STARTUP_COUNT + #define LUA_TASK_PRIO USER_TASK_PRIO_0 #define LUA_PROCESS_LINE_SIG 2 // LUAI_OPTIMIZE_DEBUG 0 = Keep all debug; 1 = keep line number info; 2 = remove all debug diff --git a/app/lua53/lua.c b/app/lua53/lua.c index 3e57895d..1118f8bd 100644 --- a/app/lua53/lua.c +++ b/app/lua53/lua.c @@ -216,6 +216,8 @@ static void dojob (lua_State *L) { static int pmain (lua_State *L) { const char *init = LUA_INIT_STRING; int status; + STARTUP_COUNT; + lua_gc(L, LUA_GCSTOP, 0); /* stop GC during initialization */ luaL_openlibs(L); /* Nodemcu open will throw to signal an LFS reload */ #ifdef LUA_VERSION_51 @@ -230,7 +232,9 @@ static int pmain (lua_State *L) { lua_input_string(" \n", 2); /* queue CR to issue first prompt */ #ifndef DISABLE_STARTUP_BANNER - print_version(L); + if ((platform_rcr_get_startup_option() & STARTUP_OPTION_NO_BANNER) == 0) { + print_version(L); + } #endif /* * And last of all, kick off application initialisation. Note that if @@ -238,6 +242,7 @@ static int pmain (lua_State *L) { * then attempting the open will trigger a file system format. */ platform_rcr_read(PLATFORM_RCR_INITSTR, (void**) &init); + STARTUP_COUNT; if (init[0] == '!') { /* !module is a compile-free way of executing LFS module */ luaL_pushlfsmodule(L); lua_pushstring(L, init+1); @@ -252,10 +257,12 @@ static int pmain (lua_State *L) { luaL_loadfile(L, init+1) : luaL_loadbuffer(L, init, strlen(init), "=INIT"); } + STARTUP_COUNT; if (status == LUA_OK) status = docall(L, 0); if (status != LUA_OK) l_print (L, 1); + STARTUP_COUNT; return 0; } diff --git a/app/modules/file.c b/app/modules/file.c index 4d6a6f98..6129f1b8 100644 --- a/app/modules/file.c +++ b/app/modules/file.c @@ -4,6 +4,7 @@ #include "lauxlib.h" #include "lmem.h" #include "platform.h" +#include "spiffs/nodemcu_spiffs.h" #include #include "vfs.h" @@ -29,6 +30,17 @@ typedef struct _file_fd_ud { int fd; } file_fd_ud; +static void do_flash_mount() { + if (!vfs_mount("/FLASH", 0)) { + // Failed to mount -- try reformat + dbg_printf("Formatting file system. Please wait...\n"); + if (!vfs_format()) { + NODE_ERR( "\n*** ERROR ***: unable to format. FS might be compromised.\n" ); + NODE_ERR( "It is advised to re-flash the NodeMCU image.\n" ); + } + } +} + static void table2tm( lua_State *L, vfs_time *tm ) { int idx = lua_gettop( L ); @@ -703,13 +715,11 @@ LROT_END(file, NULL, 0) int luaopen_file( lua_State *L ) { - if (!vfs_mount("/FLASH", 0)) { - // Failed to mount -- try reformat - dbg_printf("Formatting file system. Please wait...\n"); - if (!vfs_format()) { - NODE_ERR( "\n*** ERROR ***: unable to format. FS might be compromised.\n" ); - NODE_ERR( "It is advised to re-flash the NodeMCU image.\n" ); - } + int startup_option = platform_rcr_get_startup_option(); + if ((startup_option & STARTUP_OPTION_DELAY_MOUNT) == 0) { + do_flash_mount(); + } else { + myspiffs_set_automount(do_flash_mount); } luaL_rometatable( L, "file.vol", LROT_TABLEREF(file_vol)); luaL_rometatable( L, "file.obj", LROT_TABLEREF(file_obj)); diff --git a/app/modules/node.c b/app/modules/node.c index 8192d8cd..683c1f25 100644 --- a/app/modules/node.c +++ b/app/modules/node.c @@ -16,6 +16,10 @@ #define CPU80MHZ 80 #define CPU160MHZ 160 +#ifdef PLATFORM_STARTUP_COUNT +platform_startup_counts_t platform_startup_counts; +#endif + #define DELAY2SEC 2000 #ifndef LUA_MAXINTEGER @@ -52,8 +56,8 @@ static int node_setonerror( lua_State* L ) { return 0; } - // Lua: startupcommand(string) +// The lua.startup({command="string"}) should be used instead static int node_startupcommand( lua_State* L ) { size_t l, lrcr; const char *cmd = luaL_checklstring(L, 1, &l); @@ -62,6 +66,91 @@ static int node_startupcommand( lua_State* L ) { return 1; } +// Lua: startup([table]) +static int node_startup( lua_State* L ) { + uint32_t option, *option_p; + + option = 0; + + if (platform_rcr_read(PLATFORM_RCR_STARTUP_OPTION, (void **) &option_p) == sizeof(option)) { + option = *option_p; + } + + if (lua_gettop(L) > 0) { + // Lets hope it is a table + luaL_checktype(L, 1, LUA_TTABLE); + + int has_entries = 0; + lua_pushnil(L); + while (lua_next(L, 1) != 0) { + if (lua_isstring(L, -2)) { + const char *key = lua_tostring(L, -2); + has_entries++; + + if (strcmp(key, "command") == 0) { + size_t l, lrcr; + const char *cmd = luaL_checklstring(L, -1, &l); + lrcr = platform_rcr_write(PLATFORM_RCR_INITSTR, cmd, l+1); + if (lrcr == ~0) { + return luaL_error( L, "failed to set command" ); + } + } + + if (strcmp(key, "banner") == 0) { + int enable = lua_toboolean(L, -1); + option = (option & ~STARTUP_OPTION_NO_BANNER) | (enable ? 0 : STARTUP_OPTION_NO_BANNER); + } + + if (strcmp(key, "frequency") == 0) { + int frequency = lua_tointeger(L, -1); + option = (option & ~STARTUP_OPTION_CPU_FREQ_MAX) | (frequency == CPU160MHZ ? STARTUP_OPTION_CPU_FREQ_MAX : 0); + } + + if (strcmp(key, "delay_mount") == 0) { + int enable = lua_toboolean(L, -1); + option = (option & ~STARTUP_OPTION_DELAY_MOUNT) | (enable ? STARTUP_OPTION_DELAY_MOUNT : 0); + } + } + lua_pop(L, 1); + } + + if (has_entries) { + platform_rcr_write(PLATFORM_RCR_STARTUP_OPTION, &option, sizeof(option)); + } else { + // This is a special reset everything case + platform_rcr_delete(PLATFORM_RCR_STARTUP_OPTION); + platform_rcr_delete(PLATFORM_RCR_INITSTR); + option = 0; + } + } + + // Now we construct the return table + lua_createtable(L, 0, 4); + + const char *init_string; + size_t l; + + l = platform_rcr_read(PLATFORM_RCR_INITSTR, (void **) &init_string); + if (l != ~0) { + // when reading it back it can be padded with nulls + while (l > 0 && init_string[l - 1] == 0) { + l--; + } + lua_pushlstring(L, init_string, l); + lua_setfield(L, -2, "command"); + } + + lua_pushboolean(L, !(option & STARTUP_OPTION_NO_BANNER)); + lua_setfield(L, -2, "banner"); + + lua_pushboolean(L, (option & STARTUP_OPTION_DELAY_MOUNT)); + lua_setfield(L, -2, "delay_mount"); + + lua_pushinteger(L, (option & STARTUP_OPTION_CPU_FREQ_MAX) ? CPU160MHZ : CPU80MHZ); + lua_setfield(L, -2, "frequency"); + + return 1; +} // Lua: restart() static int node_restart( lua_State* L ) @@ -625,6 +714,30 @@ static int node_random (lua_State *L) { return 1; } +// Just return the startup as an array of tables +static int node_startup_counts(lua_State *L) { + // If the first argument is a number, then add an entry for that line + if (lua_isnumber(L, 1)) { + int lineno = lua_tointeger(L, 1); + STARTUP_ENTRY(lineno); + } + lua_createtable(L, platform_startup_counts.used, 0); + for (int i = 0; i < platform_startup_counts.used; i++) { + const platform_count_entry_t *p = &platform_startup_counts.entries[i]; + + lua_createtable(L, 0, 3); + lua_pushstring(L, p->name); + lua_setfield(L, -2, "name"); + lua_pushinteger(L, p->line); + lua_setfield(L, -2, "line"); + lua_pushinteger(L, p->ccount); + lua_setfield(L, -2, "ccount"); + + lua_rawseti(L, -2, i + 1); + } + return 1; +} + #ifdef DEVELOPMENT_TOOLS // Lua: rec = node.readrcr(id) static int node_readrcr (lua_State *L) { @@ -907,6 +1020,7 @@ LROT_BEGIN(node, NULL, 0) LROT_TABENTRY( LFS, node_lfs ) LROT_FUNCENTRY( setonerror, node_setonerror ) LROT_FUNCENTRY( startupcommand, node_startupcommand ) + LROT_FUNCENTRY( startup, node_startup ) LROT_FUNCENTRY( restart, node_restart ) LROT_FUNCENTRY( dsleep, node_deepsleep ) LROT_FUNCENTRY( dsleepMax, dsleepMax ) @@ -917,6 +1031,9 @@ LROT_BEGIN(node, NULL, 0) #ifdef DEVELOPMENT_TOOLS LROT_FUNCENTRY( readrcr, node_readrcr ) LROT_FUNCENTRY( writercr, node_writercr ) +#endif +#ifdef PLATFORM_STARTUP_COUNT + LROT_FUNCENTRY( startupcounts, node_startup_counts ) #endif LROT_FUNCENTRY( chipid, node_chipid ) LROT_FUNCENTRY( flashid, node_flashid ) diff --git a/app/platform/platform.c b/app/platform/platform.c index ab8a1acd..8add4464 100644 --- a/app/platform/platform.c +++ b/app/platform/platform.c @@ -985,6 +985,20 @@ uint32_t platform_rcr_read (uint8_t rec_id, void **rec) { return ~0; } +uint32_t platform_rcr_get_startup_option() { + static uint32_t option = ~0; + uint32_t *option_p; + + if (option == ~0) { + option = 0; + + if (platform_rcr_read(PLATFORM_RCR_STARTUP_OPTION, (void **) &option_p) == sizeof(*option_p)) { + option = *option_p; + } + } + return option; +} + uint32_t platform_rcr_delete (uint8_t rec_id) { uint32_t *rec = NULL; platform_rcr_read(rec_id, (void**)&rec); diff --git a/app/platform/platform.h b/app/platform/platform.h index 2c996d0b..f30a596d 100644 --- a/app/platform/platform.h +++ b/app/platform/platform.h @@ -347,13 +347,19 @@ void* platform_print_deprecation_note( const char *msg, const char *time_frame); #define PLATFORM_RCR_REFLASH 0x3 #define PLATFORM_RCR_FLASHLFS 0x4 #define PLATFORM_RCR_INITSTR 0x5 +#define PLATFORM_RCR_STARTUP_OPTION 0x6 #define PLATFORM_RCR_FREE 0xFF typedef union { uint32_t hdr; struct { uint8_t len,id; }; } platform_rcr_t; +#define STARTUP_OPTION_NO_BANNER (1 << 0) +#define STARTUP_OPTION_CPU_FREQ_MAX (1 << 1) +#define STARTUP_OPTION_DELAY_MOUNT (1 << 2) + uint32_t platform_rcr_read (uint8_t rec_id, void **rec); +uint32_t platform_rcr_get_startup_option(); uint32_t platform_rcr_delete (uint8_t rec_id); uint32_t platform_rcr_write (uint8_t rec_id, const void *rec, uint8_t size); @@ -384,4 +390,29 @@ static inline bool platform_post(uint8 prio, platform_task_handle_t handle, plat // Get current value of CCOUNt register #define CCOUNT_REG ({ int32_t r; asm volatile("rsr %0, ccount" : "=r"(r)); r;}) +typedef struct { + const char *name; + int line; + int32_t ccount; +} platform_count_entry_t; + +typedef struct { + int used; + platform_count_entry_t entries[32]; +} platform_startup_counts_t; + +extern platform_startup_counts_t platform_startup_counts; + +#define PLATFORM_STARTUP_COUNT_ENTRIES (sizeof(platform_startup_counts.entries) \ + / sizeof(platform_startup_counts.entries[0])) + +#ifdef PLATFORM_STARTUP_COUNT +#define STARTUP_ENTRY(lineno) do { if (platform_startup_counts.used < PLATFORM_STARTUP_COUNT_ENTRIES) {\ + platform_count_entry_t *p = &platform_startup_counts.entries[platform_startup_counts.used++]; \ + p->name = __func__; p->ccount = CCOUNT_REG; p->line = lineno; } } while(0) +#else +#define STARTUP_ENTRY(line) +#endif +#define STARTUP_COUNT STARTUP_ENTRY(__LINE__) + #endif diff --git a/app/spiffs/nodemcu_spiffs.h b/app/spiffs/nodemcu_spiffs.h index 959a1cab..1c4c02c9 100644 --- a/app/spiffs/nodemcu_spiffs.h +++ b/app/spiffs/nodemcu_spiffs.h @@ -23,4 +23,6 @@ #define SPIFFS_GC_MAX_RUNS 256 #define SPIFFS_SECURE_ERASE 0 + +extern void myspiffs_set_automount(); #endif diff --git a/app/spiffs/spiffs.c b/app/spiffs/spiffs.c index 50a80f18..6984dd9e 100644 --- a/app/spiffs/spiffs.c +++ b/app/spiffs/spiffs.c @@ -21,6 +21,8 @@ static spiffs fs; +static void (*automounter)(); + #define LOG_PAGE_SIZE 256 #define LOG_BLOCK_SIZE (INTERNAL_FLASH_SECTOR_SIZE * 2) #define LOG_BLOCK_SIZE_SMALL_FS (INTERNAL_FLASH_SECTOR_SIZE) @@ -121,6 +123,7 @@ static bool myspiffs_set_cfg(spiffs_config *cfg, bool force_create) { static bool myspiffs_mount(bool force_mount) { + STARTUP_COUNT; spiffs_config cfg; if (!myspiffs_set_cfg(&cfg, force_mount) && !force_mount) { return FALSE; @@ -142,6 +145,7 @@ static bool myspiffs_mount(bool force_mount) { // myspiffs_check_callback); 0); NODE_DBG("mount res: %d, %d\n", res, fs.err_code); + STARTUP_COUNT; return res == SPIFFS_OK; } @@ -503,12 +507,21 @@ static void myspiffs_vfs_clearerr( void ) { SPIFFS_clearerr( &fs ); } +// The callback will be called on the first file operation +void myspiffs_set_automount(void (*mounter)()) { + automounter = mounter; +} // --------------------------------------------------------------------------- // VFS interface functions // vfs_fs_fns *myspiffs_realm( const char *inname, char **outname, int set_current_drive ) { + if (automounter) { + void (*mounter)() = automounter; + automounter = NULL; + mounter(); + } if (inname[0] == '/') { // logical drive is specified, check if it's our id if (0 == strncmp(inname + 1, MY_LDRV_ID, sizeof(MY_LDRV_ID)-1)) { diff --git a/app/user/user_main.c b/app/user/user_main.c index fc319386..bdba5031 100644 --- a/app/user/user_main.c +++ b/app/user/user_main.c @@ -126,11 +126,20 @@ extern void _ResetHandler(void); * configure the PT, etc during provisioning. */ void user_pre_init(void) { + STARTUP_COUNT; #ifdef LUA_USE_MODULES_RTCTIME // Note: Keep this as close to call_user_start() as possible, since it // is where the cpu clock actually gets bumped to 80MHz. rtctime_early_startup (); #endif + int startup_option = platform_rcr_get_startup_option(); + + if (startup_option & STARTUP_OPTION_CPU_FREQ_MAX) { + REG_SET_BIT(0x3ff00014, BIT(0)); + ets_update_cpu_frequency(SYS_CPU_160MHZ); + } + int no_banner = startup_option & STARTUP_OPTION_NO_BANNER; + partition_item_t *rcr_pt = NULL, *pt; enum flash_size_map fs_size_code = system_get_flash_size_map(); // Flash size lookup is SIZE_256K*2^N where N is as follows (see SDK/user_interface.h) @@ -146,7 +155,9 @@ void user_pre_init(void) { os_printf("Flash size (%u) too small to support NodeMCU\n", flash_size); return; } else { - os_printf("system SPI FI size:%u, Flash size: %u\n", fs_size_code, flash_size ); + if (!no_banner) { + os_printf("system SPI FI size:%u, Flash size: %u\n", fs_size_code, flash_size ); + } } pt = os_malloc_iram(i); // We will work on and register a copy of the PT in iRAM @@ -167,6 +178,10 @@ void user_pre_init(void) { // Now register the partition and return if( fs_size_code > 1 && system_partition_table_regist(pt, n, fs_size_code)) { + if (no_banner) { + system_set_os_print(0); + } + STARTUP_COUNT; return; } os_printf("Invalid system partition table\n"); @@ -293,6 +308,7 @@ uint32 ICACHE_RAM_ATTR user_iram_memory_is_enabled(void) { } void nodemcu_init(void) { + STARTUP_COUNT; NODE_DBG("Task task_lua starting.\n"); // Call the Lua bootstrap startup directly. This uses the task interface // internally to carry out the main lua libraries initialisation. diff --git a/docs/modules/node.md b/docs/modules/node.md index 7a46b4fb..8abae693 100644 --- a/docs/modules/node.md +++ b/docs/modules/node.md @@ -582,9 +582,9 @@ Put NodeMCU in light sleep mode to reduce current consumption. ## node.startupcommand() -Overrides the default startup action on processor restart, preplacing the executing `init.lua` if it exists. +Overrides the default startup action on processor restart, preplacing the executing `init.lua` if it exists. This is now deprecated in favor of `node.startup({command="the command"})`. -####Syntax +#### Syntax `node.startupcommand(string)` #### Parameters @@ -607,6 +607,78 @@ node.startupcommand("=if LFS.init then LFS.init() else dofile('init.lua') end") ``` +## node.startupcounts() + +Query the performance of system startup. + +!!! Important + + This function is only available if the firmware is built with `PLATFORM_STARTUP_COUNT` defined. This would normally be done by uncommenting the `#define PLATFORM_STARTUP_COUNT` line in `app/include/user_config.h`. + +#### Syntax +`node.startupcounts([marker])` + +#### Parameters + +- `marker` If present, this will add another entry into the startup counts + +#### Returns +An array of tables which indicate how many CPU cycles had been consumed at each step of platform boot. + +#### Example +```lua +=sjson.encode(node.startupcounts()) +``` + +This might generate the output (formatted for readability): + +``` +[ + {"ccount":3774328,"name":"user_pre_init","line":124}, + {"ccount":3842297,"name":"user_pre_init","line":180}, + {"ccount":9849869,"name":"user_init","line":327}, + {"ccount":10008843,"name":"nodemcu_init","line":293}, + {"ccount":10295779,"name":"pmain","line":234}, + {"ccount":11378766,"name":"pmain","line":256}, + {"ccount":11565912,"name":"pmain","line":260}, + {"ccount":12158242,"name":"node_startup_counts","line":1}, + {"ccount":12425790,"name":"myspiffs_mount","line":126}, + {"ccount":12741862,"name":"myspiffs_mount","line":148}, + {"ccount":13983567,"name":"pmain","line":265} +] +``` + +The crucial entry is the one for `node_startup_counts` which is when the application had started running. This was on a Wemos D1 Mini with flash running at 80MHz. The startup options were all turned on. +Note that the clock speed changes in `user_pre_init` to 160MHz. The total time was (approximately): `3.8 / 80 + (12 - 3.8) / 160 = 98ms`. With startup options of 0, the time is 166ms. These times may be slightly optimistic as the clock is only 52MHz for a time during boot. + +## node.startup() + +Get/set options that control the startup process. This interface will grow over time. + +#### Syntax +`node.startup([{table}])` + +#### Parameters + +If the argument is omitted, then no change is made to the current set of startup options. If the argument is the empty table `{}` then all options are +reset to their default values. + +- `table` one or more options: + - `banner` - set to true or false to indicate whether the startup banner should be displayed or not. (default: true) + - `frequency` - set to node.CPU80MHZ or node.CPU160MHZ to indicate the initial CPU speed. (default: node.CPU80MHZ) + - `delay_mount` - set to true or false to indicate whether the SPIFFS filesystem mount is delayed until it is first needed or not. (default: false) + - `command` - set to a string which is the initial command that is run. This is the same string as in the `node.startupcommand`. + +#### Returns +`table` This is the complete set of options in the state that will take effect on the next boot. Note that the `command` key may be missing -- in which + case the default value will be used. + +#### Example +```lua +node.startup({banner=false, frequency=node.CPU160MHZ}) -- Prevent printing the banner and run at 160MHz +``` + + ## node.stripdebug() Controls the amount of debug information kept during [`node.compile()`](#nodecompile), and allows removal of debug information from already compiled Lua code. @@ -765,4 +837,3 @@ priority is 2 priority is 1 priority is 0 ``` -