You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@nuttx.apache.org by xi...@apache.org on 2021/07/02 13:25:12 UTC
[incubator-nuttx] 04/04: sched: add CONFIG_SCHED_CRITMONITOR_XX for
debugging system lantency
This is an automated email from the ASF dual-hosted git repository.
xiaoxiang pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-nuttx.git
commit adfaa140cc1a845d6f402b1d1569f12cfd8d4b57
Author: ligd <li...@xiaomi.com>
AuthorDate: Thu Apr 29 19:41:27 2021 +0800
sched: add CONFIG_SCHED_CRITMONITOR_XX for debugging system lantency
Change-Id: Id2a75db28caf1a89552e33391bd90f85cde08dbd
Signed-off-by: ligd <li...@xiaomi.com>
---
sched/Kconfig | 52 ++++++++++++++++++++++++++++++
sched/irq/irq_dispatch.c | 10 ++++++
sched/sched/sched_critmonitor.c | 71 +++++++++++++++++++++++++++++++++++++++++
sched/wdog/wd_start.c | 26 ++++++++++++++-
sched/wqueue/kwork_process.c | 27 +++++++++++++++-
5 files changed, 184 insertions(+), 2 deletions(-)
diff --git a/sched/Kconfig b/sched/Kconfig
index ba0246e..644f0cb 100644
--- a/sched/Kconfig
+++ b/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
diff --git a/sched/irq/irq_dispatch.c b/sched/irq/irq_dispatch.c
index 489de37..ab984a0 100644
--- a/sched/irq/irq_dispatch.c
+++ b/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
diff --git a/sched/sched/sched_critmonitor.c b/sched/sched/sched_critmonitor.c
index 97862b7..76a1656 100644
--- a/sched/sched/sched_critmonitor.c
+++ b/sched/sched/sched_critmonitor.c
@@ -33,6 +33,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);
}
}
}
diff --git a/sched/wdog/wd_start.c b/sched/wdog/wd_start.c
index 531ec3a..d285fc7 100644
--- a/sched/wdog/wd_start.c
+++ b/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);
}
}
}
diff --git a/sched/wqueue/kwork_process.c b/sched/wqueue/kwork_process.c
index 22352bc..9bec97e 100644
--- a/sched/wqueue/kwork_process.c
+++ b/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