sched: add configuration to record the busy waiting time

Documentation/implementation/critical_sections.rst

@@ -257,6 +257,14 @@ and preemption operations. Only have instructions when scheduler triggers contex
 * >= 0 to enable critical section entered time statistic, data will be in critmon procfs.
 * > 0 to also do alert log when critical section entered time above the configuration ticks.
 
+**Critical section pre-entry busywait time**::
+
+  CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT=-1
+
+* Default -1 to disable critical section pre-entry busywait time statistic.
+* >= 0 to enable critical section pre-entry busywait time statistic, data will be in critmon procfs.
+* > 0 to also do alert log when critical section pre-entry busywait time above the configuration ticks.
+
 **Irq executing time**::
 
   CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ=-1

fs/procfs/fs_procfscritmon.c

@@ -190,6 +190,11 @@ static ssize_t critmon_read_cpu(FAR struct critmon_file_s *attr,
   size_t linesize;
   size_t copysize;
   size_t totalsize;
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+  struct timespec all_time;
+  clock_t elapsed;
+  uint32_t rate;
+#endif
 
   UNUSED(maxtime);
   UNUSED(linesize);
@@ -279,6 +284,74 @@ static ssize_t critmon_read_cpu(FAR struct critmon_file_s *attr,
     }
 #endif
 
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+  /* Convert and generate output for max busywait time when trying spinlock */
+
+  if (g_busywait_max[cpu] > 0)
+    {
+      perf_convert(g_busywait_max[cpu], &maxtime);
+    }
+  else
+    {
+      maxtime.tv_sec = 0;
+      maxtime.tv_nsec = 0;
+    }
+
+  /* Reset the maximum */
+
+  g_busywait_max[cpu] = 0;
+
+  /* Generate output for max busywait time to enter csection(get spinlock) */
+
+  linesize = procfs_snprintf(attr->line, CRITMON_LINELEN, ",%lu.%09lu",
+                             (unsigned long)maxtime.tv_sec,
+                             (unsigned long)maxtime.tv_nsec);
+  copysize = procfs_memcpy(attr->line, linesize, buffer, buflen, offset);
+
+  totalsize += copysize;
+  buffer    += copysize;
+  buflen    -= copysize;
+
+  if (buflen <= 0)
+    {
+      return totalsize;
+    }
+
+  /* Convert and generate output for all busywait time when trying spinlock */
+
+  if (g_busywait_total[cpu] > 0)
+    {
+      perf_convert(g_busywait_total[cpu], &all_time);
+    }
+  else
+    {
+      all_time.tv_sec = 0;
+      all_time.tv_nsec = 0;
+    }
+
+  elapsed = clock() * CONFIG_USEC_PER_TICK;
+  rate = (uint64_t)(all_time.tv_sec * 1000000 + all_time.tv_nsec / 1000) *
+         1000000 / elapsed;
+
+  /* Generate output for all busywait time to enter csection(get spinlock) */
+
+  linesize = procfs_snprintf(attr->line, CRITMON_LINELEN, ",%lu.%09lu %2"
+                             PRId32 ".%04" PRId32 "%%",
+                             (unsigned long)all_time.tv_sec,
+                             (unsigned long)all_time.tv_nsec,
+                             rate / 10000, rate % 10000);
+  copysize = procfs_memcpy(attr->line, linesize, buffer, buflen, offset);
+
+  totalsize += copysize;
+  buffer    += copysize;
+  buflen    -= copysize;
+
+  if (buflen <= 0)
+    {
+      return totalsize;
+    }
+#endif
+
   linesize = procfs_snprintf(attr->line, CRITMON_LINELEN, "\n");
   copysize = procfs_memcpy(attr->line, linesize, buffer, buflen, offset);
 

fs/procfs/fs_procfsproc.c

@@ -844,6 +844,69 @@ static ssize_t proc_critmon(FAR struct proc_file_s *procfile,
     }
 #endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 */
 
+  /* Convert and generate output for max busywait time && all busywait time */
+
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+  if (tcb->busywait_max > 0)
+    {
+      perf_convert(tcb->busywait_max, &maxtime);
+    }
+  else
+    {
+      maxtime.tv_sec = 0;
+      maxtime.tv_nsec = 0;
+    }
+
+  /* Reset the maximum */
+
+  tcb->busywait_max = 0;
+
+  /* Generate output for max busywait time */
+
+  linesize = procfs_snprintf(procfile->line, STATUS_LINELEN, "%lu.%09lu %p,",
+                             (unsigned long)maxtime.tv_sec,
+                             (unsigned long)maxtime.tv_nsec,
+                             tcb->busywait_max_caller);
+  copysize = procfs_memcpy(procfile->line, linesize, buffer, remaining,
+                           &offset);
+
+  totalsize += copysize;
+  buffer    += copysize;
+  remaining -= copysize;
+
+  if (totalsize >= buflen)
+    {
+      return totalsize;
+    }
+
+  if (tcb->busywait_total > 0)
+    {
+      perf_convert(tcb->busywait_total, &maxtime);
+    }
+  else
+    {
+      maxtime.tv_sec = 0;
+      maxtime.tv_nsec = 0;
+    }
+
+  /* Generate output for all busywait time */
+
+  linesize = procfs_snprintf(procfile->line, STATUS_LINELEN, "%lu.%09lu,",
+                             (unsigned long)maxtime.tv_sec,
+                             (unsigned long)maxtime.tv_nsec);
+  copysize = procfs_memcpy(procfile->line, linesize, buffer, remaining,
+                           &offset);
+
+  totalsize += copysize;
+  buffer    += copysize;
+  remaining -= copysize;
+
+  if (totalsize >= buflen)
+    {
+      return totalsize;
+    }
+#endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 */
+
   /* Convert and generate output for maximum time thread running */
 #if CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD >= 0
   if (tcb->run_max > 0)

include/nuttx/irq.h

@@ -146,6 +146,10 @@
 #  define CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION -1
 #endif
 
+#ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT
+#  define CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT -1
+#endif
+
 #ifndef CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ
 #  define CONFIG_SCHED_CRITMONITOR_MAXTIME_IRQ -1
 #endif
@@ -325,6 +329,7 @@ int irqchain_detach(int irq, xcpt_t isr, FAR void *arg);
 
 #ifdef CONFIG_IRQCOUNT
 #  if CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 || \
+      CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 || \
       defined(CONFIG_SCHED_INSTRUMENTATION_CSECTION)
 irqstate_t enter_critical_section(void) noinstrument_function;
 #  else

include/nuttx/sched.h

@@ -701,6 +701,14 @@ struct tcb_s
   void   *crit_max_caller;               /* Caller of max critical section  */
 #endif
 
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+  clock_t busywait_start;                /* Time when thread busywait       */
+  clock_t busywait_max;                  /* Max time of busywait            */
+  clock_t busywait_total;                /* Total time of busywait          */
+  void   *busywait_caller;               /* Caller of busywait              */
+  void   *busywait_max_caller;           /* Caller of max busywait          */
+#endif
+
   /* State save areas *******************************************************/
 
   /* The form and content of these fields are platform-specific.            */
@@ -821,6 +829,11 @@ EXTERN clock_t g_preemp_max[CONFIG_SMP_NCPUS];
 EXTERN clock_t g_crit_max[CONFIG_SMP_NCPUS];
 #endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 */
 
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+EXTERN clock_t g_busywait_max[CONFIG_SMP_NCPUS];
+EXTERN clock_t g_busywait_total[CONFIG_SMP_NCPUS];
+#endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 */
+
 /* g_running_tasks[] holds a references to the running task for each CPU.
  * It is valid only when up_interrupt_context() returns true.
  */

include/nuttx/spinlock.h

@@ -66,6 +66,12 @@ void sched_note_spinlock_unlock(FAR volatile spinlock_t *spinlock);
 #  define sched_note_spinlock_unlock(spinlock)
 #endif
 
+#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0
+void nxsched_critmon_busywait(bool state, FAR void *caller);
+#else
+#  define nxsched_critmon_busywait(state, caller)
+#endif
+
 /****************************************************************************
  * Public Data Types
  ****************************************************************************/
@@ -223,10 +229,18 @@ static inline_function void spin_lock(FAR volatile spinlock_t *lock)
 
   sched_note_spinlock_lock(lock);
 
+  /* If CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0, count busy-waiting. */
+
+  nxsched_critmon_busywait(true, return_address(0));
+
   /* Lock without trace note */
 
   spin_lock_notrace(lock);
 
+  /* Get the lock, end counting busy-waiting */
+
+  nxsched_critmon_busywait(false, return_address(0));
+
   /* Notify that we have the spinlock */
 
   sched_note_spinlock_locked(lock);
@@ -477,10 +491,18 @@ irqstate_t spin_lock_irqsave(FAR volatile spinlock_t *lock)
 
   sched_note_spinlock_lock(lock);
 
+  /* If CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0, count busy-waiting. */
+
+  nxsched_critmon_busywait(true, return_address(0));
+
   /* Lock without trace note */
 
   flags = spin_lock_irqsave_notrace(lock);
 
+  /* Get the lock, end counting busy-waiting */
+
+  nxsched_critmon_busywait(false, return_address(0));
+
   /* Notify that we have the spinlock */
 
   sched_note_spinlock_locked(lock);
@@ -918,6 +940,8 @@ void rspin_restorelock(FAR rspinlock_t *lock, uint16_t count)
 
 static inline_function void read_lock(FAR volatile rwlock_t *lock)
 {
+  nxsched_critmon_busywait(true, return_address(0));
+
   while (true)
     {
       int old = atomic_read(lock);
@@ -934,6 +958,8 @@ static inline_function void read_lock(FAR volatile rwlock_t *lock)
     }
 
   UP_DMB();
+
+  nxsched_critmon_busywait(false, return_address(0));
 }
 
 /****************************************************************************
@@ -1036,6 +1062,8 @@ static inline_function void read_unlock(FAR volatile rwlock_t *lock)
 
 static inline_function void write_lock(FAR volatile rwlock_t *lock)
 {
+  nxsched_critmon_busywait(true, return_address(0));
+
   while (true)
     {
       int zero = RW_SP_UNLOCKED;
@@ -1049,6 +1077,8 @@ static inline_function void write_lock(FAR volatile rwlock_t *lock)
     }
 
   UP_DMB();
+
+  nxsched_critmon_busywait(false, return_address(0));
 }
 
 /****************************************************************************

sched/Kconfig

@@ -955,6 +955,15 @@ config SCHED_CRITMONITOR_MAXTIME_CSECTION
 		SCHED_CRITMONITOR_MAXTIME_CSECTION, or system will give a warning.
 		For debugging system latency, 0 means disabled.
 
+config SCHED_CRITMONITOR_MAXTIME_BUSYWAIT
+	int "Critical section or spinlock max busy waiting time"
+	default -1
+	---help---
+		Busy waiting time to enter critical section or
+		get spinlock should be smaller than
+		SCHED_CRITMONITOR_MAXTIME_BUSYWAIT, or system will give a warning.
+		For debugging system latency, -1 means disabled.
+
 config SCHED_CRITMONITOR_MAXTIME_IRQ
 	int "IRQ max execution time"
 	default SCHED_CRITMONITOR_MAXTIME_CSECTION
@@ -981,6 +990,7 @@ config SCHED_CRITMONITOR_MAXTIME_PANIC
 		SCHED_CRITMONITOR_MAXTIME_WQUEUE > 0 || \
 		SCHED_CRITMONITOR_MAXTIME_PREEMPTION > 0 || \
 		SCHED_CRITMONITOR_MAXTIME_CSECTION > 0 || \
+		SCHED_CRITMONITOR_MAXTIME_BUSYWAIT > 0 || \
 		SCHED_CRITMONITOR_MAXTIME_IRQ > 0
 	default n
 	---help---

sched/irq/irq_csection.c

@@ -285,13 +285,25 @@ irqstate_t enter_critical_section_notrace(void)
 #endif
 
 #if CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 || \
+    CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 || \
     defined(CONFIG_SCHED_INSTRUMENTATION_CSECTION)
 irqstate_t enter_critical_section(void)
 {
   FAR struct tcb_s *rtcb;
   irqstate_t flags;
+
+  /* If CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0,
+   * start counting time of busy-waiting.
+   */
+
+  nxsched_critmon_busywait(true, return_address(0));
+
   flags = enter_critical_section_notrace();
 
+  /* Get the lock, end counting busy-waiting */
+
+  nxsched_critmon_busywait(false, return_address(0));
+
   if (!up_interrupt_context())
     {
       rtcb = this_task();
@@ -446,6 +458,7 @@ void leave_critical_section_notrace(irqstate_t flags)
 #endif
 
 #if CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 || \
+    CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 || \
     defined(CONFIG_SCHED_INSTRUMENTATION_CSECTION)
 void leave_critical_section(irqstate_t flags)
 {