diff --git a/sched/Kconfig b/sched/Kconfig index dd4bb576b11..ba35aee80ff 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 489de370fac..1ba89546949 100644 --- a/sched/irq/irq_dispatch.c +++ b/sched/irq/irq_dispatch.c @@ -83,6 +83,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 3ae0e0d4e98..a9a3268f676 100644 --- a/sched/sched/sched_critmonitor.c +++ b/sched/sched/sched_critmonitor.c @@ -31,6 +31,58 @@ #ifdef CONFIG_SCHED_CRITMONITOR +/**************************************************************************** + * Pre-processor Definitions + ****************************************************************************/ + +#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 ****************************************************************************/ @@ -111,6 +163,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 */ @@ -175,6 +228,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 */ @@ -242,6 +296,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); } } @@ -269,6 +324,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); } } } @@ -295,6 +351,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? */ @@ -309,6 +366,7 @@ void nxsched_suspend_critmon(FAR struct tcb_s *tcb) if (elapsed > tcb->premp_max) { tcb->premp_max = elapsed; + CHECK_PREEMPTION(tcb->pid, elapsed); } } @@ -324,6 +382,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 5ce57119215..1ddc1d46fe8 100644 --- a/sched/wdog/wd_start.c +++ b/sched/wdog/wd_start.c @@ -50,6 +50,26 @@ # define MAX(a,b) (((a) > (b)) ? (a) : (b)) #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 ****************************************************************************/ @@ -104,7 +124,7 @@ static inline void wd_expiration(void) /* Execute the watchdog function */ up_setpicbase(wdog->picbase); - wdog->func(wdog->arg); + CALL_FUNC(wdog->func, wdog->arg); } } } diff --git a/sched/wqueue/kwork_process.c b/sched/wqueue/kwork_process.c index 78ca787de1b..4d6a069b280 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,26 @@ # define MIN(a,b) ((a) < (b) ? (a) : (b)) #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 +175,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