From adfaa140cc1a845d6f402b1d1569f12cfd8d4b57 Mon Sep 17 00:00:00 2001 From: ligd Date: Thu, 29 Apr 2021 19:41:27 +0800 Subject: [PATCH] sched: add CONFIG_SCHED_CRITMONITOR_XX for debugging system lantency Change-Id: Id2a75db28caf1a89552e33391bd90f85cde08dbd Signed-off-by: ligd --- 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 ba0246e5ed..644f0cbc2c 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 489de370fa..ab984a057c 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 97862b7ee5..76a1656456 100644 --- a/sched/sched/sched_critmonitor.c +++ b/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); } } } diff --git a/sched/wdog/wd_start.c b/sched/wdog/wd_start.c index 531ec3a910..d285fc72ec 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 22352bc210..9bec97e35d 100644 --- a/sched/wqueue/kwork_process.c +++ b/sched/wqueue/kwork_process.c @@ -24,6 +24,7 @@ #include +#include #include #include #include @@ -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