sched: add CONFIG_SCHED_CRITMONITOR_XX for debugging system lantency

Change-Id: Id2a75db28caf1a89552e33391bd90f85cde08dbd
Signed-off-by: ligd <liguiding1@xiaomi.com>

sched/Kconfig

@@ -736,6 +736,58 @@ config SCHED_CRITMONITOR
 		The second interface simply converts an elapsed time into well known
 		units for presentation by the ProcFS file system.
 
+if SCHED_CRITMONITOR
+
+config SCHED_CRITMONITOR_MAXTIME_THREAD
+	int "THREAD max execution time"
+	default 0
+	---help---
+		Thread execution time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_THREAD, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+config SCHED_CRITMONITOR_MAXTIME_WQUEUE
+	int "WORK queue max execution time"
+	default SCHED_CRITMONITOR_MAXTIME_THREAD
+	---help---
+		Worker execution time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_WQUEUE, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+config SCHED_CRITMONITOR_MAXTIME_PREEMPTION
+	int "Pre-emption (sched_lock) max holding time"
+	default SCHED_CRITMONITOR_MAXTIME_WQUEUE
+	---help---
+		Pre-emption holding time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_PREEMPTION, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+config SCHED_CRITMONITOR_MAXTIME_CSECTION
+	int "Csection (enter_critical_section) max holding time"
+	default SCHED_CRITMONITOR_MAXTIME_PREEMPTION
+	---help---
+		Csection holding time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_CSECTION, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+config SCHED_CRITMONITOR_MAXTIME_IRQ
+	int "IRQ max execution time"
+	default SCHED_CRITMONITOR_MAXTIME_CSECTION
+	---help---
+		IRQ handler execution time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_IRQ, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+config SCHED_CRITMONITOR_MAXTIME_WDOG
+	int "WDOG callback max execution time"
+	default SCHED_CRITMONITOR_MAXTIME_IRQ
+	---help---
+		Wdog callback execution time should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_WDOG, or system will give a warnning.
+		For debugging system lantency, 0 means disabled.
+
+endif # SCHED_CRITMONITOR
+
 config SCHED_CPULOAD
 	bool "Enable CPU load monitoring"
 	default n

sched/irq/irq_dispatch.c

@@ -65,6 +65,10 @@
  * interrupt request
  */
 
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ 0
+#endif
+
 #ifndef CONFIG_SCHED_IRQMONITOR
 #  define CALL_VECTOR(ndx, vector, irq, context, arg) \
      vector(irq, context, arg)
@@ -83,6 +87,12 @@
            { \
              g_irqvector[ndx].time = delta.tv_nsec; \
            } \
+         if (CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ > 0 && \
+             elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ) \
+           { \
+             serr("IRQ %d(%p), execute time too long %"PRIu32"\n", \
+                  irq, vector, elapsed); \
+           } \
        } \
      while (0)
 #else

sched/sched/sched_critmonitor.c

@@ -32,6 +32,70 @@
 
 #ifdef CONFIG_SCHED_CRITMONITOR
 
+/****************************************************************************
+ * Pre-processor Definitions
+ ****************************************************************************/
+
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_PREEMPTION
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_PREEMPTION 0
+#endif
+
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION 0
+#endif
+
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD 0
+#endif
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_PREEMPTION > 0
+#  define CHECK_PREEMPTION(pid, elapsed) \
+     do \
+       { \
+         if (pid > 0 && \
+             elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_PREEMPTION) \
+           { \
+             serr("PID %d hold sched lock too long %"PRIu32"\n", \
+                   pid, elapsed); \
+           } \
+       } \
+     while (0)
+#else
+#  define CHECK_PREEMPTION(pid, elapsed)
+#endif
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION > 0
+#  define CHECK_CSECTION(pid, elapsed) \
+     do \
+       { \
+         if (pid > 0 && \
+             elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION) \
+           { \
+             serr("PID %d hold critical section too long %"PRIu32"\n", \
+                   pid, elapsed); \
+           } \
+       } \
+     while (0)
+#else
+#  define CHECK_CSECTION(pid, elapsed)
+#endif
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD > 0
+#  define CHECK_THREAD(pid, elapsed) \
+     do \
+       { \
+         if (pid > 0 && \
+             elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD) \
+           { \
+             serr("PID %d execute too long %"PRIu32"\n", \
+                   pid, elapsed); \
+           } \
+       } \
+     while (0)
+#else
+#  define CHECK_THREAD(pid, elapsed)
+#endif
+
 /****************************************************************************
  * Private Data
  ****************************************************************************/
@@ -112,6 +176,7 @@ void nxsched_critmon_preemption(FAR struct tcb_s *tcb, bool state)
       if (elapsed > tcb->premp_max)
         {
           tcb->premp_max = elapsed;
+          CHECK_PREEMPTION(tcb->pid, elapsed);
         }
 
       /* Check for the global max elapsed time */
@@ -176,6 +241,7 @@ void nxsched_critmon_csection(FAR struct tcb_s *tcb, bool state)
       if (elapsed > tcb->crit_max)
         {
           tcb->crit_max = elapsed;
+          CHECK_CSECTION(tcb->pid, elapsed);
         }
 
       /* Check for the global max elapsed time */
@@ -243,6 +309,7 @@ void nxsched_resume_critmon(FAR struct tcb_s *tcb)
       if (elapsed > g_premp_max[cpu])
         {
           g_premp_max[cpu] = elapsed;
+          CHECK_PREEMPTION(tcb->pid, elapsed);
         }
     }
 
@@ -270,6 +337,7 @@ void nxsched_resume_critmon(FAR struct tcb_s *tcb)
       if (elapsed > g_crit_max[cpu])
         {
           g_crit_max[cpu] = elapsed;
+          CHECK_CSECTION(tcb->pid, elapsed);
         }
     }
 }
@@ -296,6 +364,7 @@ void nxsched_suspend_critmon(FAR struct tcb_s *tcb)
   if (elapsed > tcb->run_max)
     {
       tcb->run_max = elapsed;
+      CHECK_THREAD(tcb->pid, elapsed);
     }
 
   /* Did this task disable preemption? */
@@ -310,6 +379,7 @@ void nxsched_suspend_critmon(FAR struct tcb_s *tcb)
       if (elapsed > tcb->premp_max)
         {
           tcb->premp_max = elapsed;
+          CHECK_PREEMPTION(tcb->pid, elapsed);
         }
     }
 
@@ -325,6 +395,7 @@ void nxsched_suspend_critmon(FAR struct tcb_s *tcb)
       if (elapsed > tcb->crit_max)
         {
           tcb->crit_max = elapsed;
+          CHECK_CSECTION(tcb->pid, elapsed);
         }
     }
 }

sched/wdog/wd_start.c

@@ -50,6 +50,30 @@
 #  define MAX(a,b) (((a) > (b)) ? (a) : (b))
 #endif
 
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_WDOG
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_WDOG 0
+#endif
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_WDOG > 0
+#  define CALL_FUNC(func, arg) \
+     do \
+       { \
+         uint32_t start; \
+         uint32_t elapsed; \
+         start = up_critmon_gettime(); \
+         func(arg); \
+         elapsed = up_critmon_gettime() - start; \
+         if (elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_WDOG) \
+           { \
+             serr("WDOG %p, %s IRQ, execute too long %"PRIu32"\n", \
+                   func, up_interrupt_context() ? "IN" : "NOT", elapsed); \
+           } \
+       } \
+     while (0)
+#else
+#  define CALL_FUNC(func, arg) func(arg)
+#endif
+
 /****************************************************************************
  * Private Functions
  ****************************************************************************/
@@ -106,7 +130,7 @@ static inline void wd_expiration(void)
           /* Execute the watchdog function */
 
           up_setpicbase(wdog->picbase);
-          func(wdog->arg);
+          CALL_FUNC(func, wdog->arg);
         }
     }
 }

sched/wqueue/kwork_process.c

@@ -24,6 +24,7 @@
 
 #include <nuttx/config.h>
 
+#include <debug.h>
 #include <stdint.h>
 #include <unistd.h>
 #include <signal.h>
@@ -63,6 +64,30 @@
 #  define MIN(a,b) ((a) < (b) ? (a) : (b))
 #endif
 
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_WQUEUE
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_WQUEUE 0
+#endif
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_WQUEUE > 0
+#  define CALL_WORKER(worker, arg) \
+     do \
+       { \
+         uint32_t start; \
+         uint32_t elapsed; \
+         start = up_critmon_gettime(); \
+         worker(arg); \
+         elapsed = up_critmon_gettime() - start; \
+         if (elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_WQUEUE) \
+           { \
+             serr("WORKER %p execute too long %"PRIu32"\n", \
+                   worker, elapsed); \
+           } \
+       } \
+     while (0)
+#else
+#  define CALL_WORKER(worker, arg) worker(arg)
+#endif
+
 /****************************************************************************
  * Public Functions
  ****************************************************************************/
@@ -154,7 +179,7 @@ void work_process(FAR struct kwork_wqueue_s *wqueue, int wndx)
                */
 
               leave_critical_section(flags);
-              worker(arg);
+              CALL_WORKER(worker, arg);
 
               /* Now, unfortunately, since we re-enabled interrupts we don't
                * know the state of the work list and we will have to start