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

@@ -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

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
+  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;
 }
 

app/modules/file.c

@@ -4,6 +4,7 @@
 #include "lauxlib.h"
 #include "lmem.h"
 #include "platform.h"
+#include "spiffs/nodemcu_spiffs.h"
 
 #include <stdint.h>
 #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)) {
+  int startup_option = platform_rcr_get_startup_option();
-      // Failed to mount -- try reformat
+  if ((startup_option & STARTUP_OPTION_DELAY_MOUNT) == 0) {
-      dbg_printf("Formatting file system. Please wait...\n");
+      do_flash_mount();
-      if (!vfs_format()) {
+  } else {
-          NODE_ERR( "\n*** ERROR ***: unable to format. FS might be compromised.\n" );
+      myspiffs_set_automount(do_flash_mount);
-          NODE_ERR( "It is advised to re-flash the NodeMCU image.\n" );
-      }
   }
   luaL_rometatable( L, "file.vol",  LROT_TABLEREF(file_vol));
   luaL_rometatable( L, "file.obj",  LROT_TABLEREF(file_obj));

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 )

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);

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

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

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)) {

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,8 +155,10 @@ void user_pre_init(void) {
         os_printf("Flash size (%u) too small to support NodeMCU\n", flash_size);
         return;
     } else {
+        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
     // Return if anything is amiss; The SDK will halt if the PT hasn't been registered
@@ -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.

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
 ```
-