system/init: Warning for long commands

If the command of an action takes too long (greater than
CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW milliseconds, 50 ms by default),
a warning log will be output for analysis and debugging.

For example:

  a. sleep 1
       [    0.340000] [ 3] [ 0] init_main: executing NSH command 'sleep 1'
       [    1.360000] [ 3] [ 0] init_main: NSH command 'sleep 1' exited 0
     > [    1.360000] [ 3] [ 0] init_main: command 'sleep' took 1020 ms

  b. hello (add sleep(1) to examples/hello)

       [    1.390000] [ 3] [ 0] init_main: executed command 'hello' pid 14
       [    1.390000] [ 3] [ 0] init_main: waiting 'hello' pid 14
       Hello, World!!
     > [    2.400000] [ 3] [ 0] init_main: command 'hello' pid 14 took 1010 ms
       [    2.400000] [ 3] [ 0] init_main: command 'hello' pid 14 exited status 0

Signed-off-by: wangjianyu3 <[email protected]>

Author: JianyuWang0623

system/init/Kconfig

@@ -58,6 +58,13 @@ config SYSTEM_INIT_ACTION_CMD_ARGS_MAX
 		   ...
 		```
 
+config SYSTEM_INIT_ACTION_WARN_SLOW
+	int "Warn if command takes too long"
+	default 50
+	depends on SYSTEM_INIT_WARN
+	---help---
+		Warning if command took more than `SYSTEM_INIT_ACTION_WARN_SLOW` ms.
+
 config SYSTEM_INIT_ACTION_MANAGER_EVENT_MAX
 	int "Max number of action manager events"
 	default 32

system/init/action.c

@@ -210,6 +210,10 @@ int init_action_run_command(FAR struct action_manager_s *am)
                                         struct action_cmd_s, node);
     }
 
+#if defined(CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW) && \
+    CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW > 0
+  clock_gettime(CLOCK_MONOTONIC, &am->time_run);
+#endif
   ret = init_builtin_run(am, am->running->argc, am->running->argv);
   if (ret > 0)
     {
@@ -229,6 +233,28 @@ void init_action_reap_command(FAR struct action_manager_s *am)
                                                    struct action_s,
                                                    ready_node);
 
+#if defined(CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW) && \
+    CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW > 0
+  struct timespec time;
+  int ms;
+
+  clock_gettime(CLOCK_MONOTONIC, &time);
+  clock_timespec_subtract(&time, &am->time_run, &time);
+  ms = TIMESPEC2MS(time);
+  if (ms > CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW)
+    {
+      if (am->pid_running <= 0)
+        {
+          init_warn("command '%s' took %d ms", am->running->argv[0], ms);
+        }
+      else
+        {
+          init_warn("command '%s' pid %d took %d ms", am->running->argv[0],
+                    am->pid_running, ms);
+        }
+    }
+#endif
+
   am->pid_running = -1;
   if (list_is_tail(&ready->cmds, &am->running->node))
     {

system/init/action.h

@@ -64,6 +64,10 @@ struct action_manager_s
 
   FAR struct action_cmd_s *running;
   int pid_running;
+#if defined(CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW) && \
+    CONFIG_SYSTEM_INIT_ACTION_WARN_SLOW > 0
+  struct timespec time_run;
+#endif
   FAR struct service_manager_s *sm;
 };
 

system/init/init.h

@@ -33,6 +33,8 @@
  * Pre-processor Definitions
  ****************************************************************************/
 
+#define TIMESPEC2MS(t) (((t).tv_sec * 1000) + (t).tv_nsec / 1000000)
+
 #ifdef CONFIG_SYSTEM_INIT_DEBUG
 #define init_debug(...) syslog(LOG_DEBUG, ##__VA_ARGS__)
 #define init_dump_args(argc, argv) \

system/init/service.c

@@ -44,7 +44,6 @@
  ****************************************************************************/
 
 #define SYSTEM_INIT_SERVICE_GENTLE_KILL_TIMEOUT 200
-#define TIMESPEC2MS(t) (((t).tv_sec * 1000) + (t).tv_nsec / 1000000)
 
 #define check_flags(s, f) ((s)->flags & (f))