This is an automated email from the ASF dual-hosted git repository. jiuzhudong pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/nuttx.git
commit 3116c19efc39c6cff297d7ec329aff0f1958ff63 Author: wangzhi16 <[email protected]> AuthorDate: Mon Nov 11 09:44:28 2024 +0800 sched/spinlock: Add configuration to record busywait. Add configuration "CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT", which can record the busy waiting time to get spinlock or enter critical section. Signed-off-by: wangzhi16 <[email protected]> --- fs/procfs/fs_procfscritmon.c | 73 ++++++++++++++++++++++++++++++++++++++ fs/procfs/fs_procfsproc.c | 63 +++++++++++++++++++++++++++++++++ include/nuttx/irq.h | 4 +++ include/nuttx/sched.h | 13 +++++++ include/nuttx/spinlock.h | 22 ++++++++++++ sched/Kconfig | 10 ++++++ sched/sched/sched_critmonitor.c | 78 +++++++++++++++++++++++++++++++++++++++++ 7 files changed, 263 insertions(+) diff --git a/fs/procfs/fs_procfscritmon.c b/fs/procfs/fs_procfscritmon.c index 96c2e88a3b0..bc05e0a4e57 100644 --- a/fs/procfs/fs_procfscritmon.c +++ b/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 alltime; + 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], &alltime); + } + else + { + alltime.tv_sec = 0; + alltime.tv_nsec = 0; + } + + elapsed = clock() * CONFIG_USEC_PER_TICK; + rate = (uint64_t)(alltime.tv_sec * 1000000 + alltime.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)alltime.tv_sec, + (unsigned long)alltime.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); diff --git a/fs/procfs/fs_procfsproc.c b/fs/procfs/fs_procfsproc.c index a1a58fe1b5a..49138a34297 100644 --- a/fs/procfs/fs_procfsproc.c +++ b/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) diff --git a/include/nuttx/irq.h b/include/nuttx/irq.h index 6f722481176..b1af8827e98 100644 --- a/include/nuttx/irq.h +++ b/include/nuttx/irq.h @@ -150,6 +150,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 diff --git a/include/nuttx/sched.h b/include/nuttx/sched.h index 6aebeb05f5d..c362cb1011e 100644 --- a/include/nuttx/sched.h +++ b/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. */ diff --git a/include/nuttx/spinlock.h b/include/nuttx/spinlock.h index 00005751bfd..fdb066d9f69 100644 --- a/include/nuttx/spinlock.h +++ b/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); @@ -988,6 +1002,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); @@ -1004,6 +1020,8 @@ static inline_function void read_lock(FAR volatile rwlock_t *lock) } UP_DMB(); + + nxsched_critmon_busywait(false, return_address(0)); } /**************************************************************************** @@ -1106,6 +1124,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; @@ -1119,6 +1139,8 @@ static inline_function void write_lock(FAR volatile rwlock_t *lock) } UP_DMB(); + + nxsched_critmon_busywait(false, return_address(0)); } /**************************************************************************** diff --git a/sched/Kconfig b/sched/Kconfig index 34db4e5d92e..bc68d2808f6 100644 --- a/sched/Kconfig +++ b/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--- diff --git a/sched/sched/sched_critmonitor.c b/sched/sched/sched_critmonitor.c index 2843d51348b..2b2637c1f42 100644 --- a/sched/sched/sched_critmonitor.c +++ b/sched/sched/sched_critmonitor.c @@ -70,6 +70,22 @@ # define CHECK_CSECTION(pid, elapsed) #endif +#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 +# define CHECK_BUSYWAIT(pid, elapsed) \ + do \ + { \ + if (pid > 0 && \ + elapsed > CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT) \ + { \ + CRITMONITOR_PANIC("PID %d wait for critical section or spin" \ + "lock too long %" PRIu32 "\n", pid, elapsed); \ + } \ + } \ + while (0) +#else +# define CHECK_BUSYWAIT(pid, elapsed) +#endif + #if CONFIG_SCHED_CRITMONITOR_MAXTIME_THREAD > 0 # define CHECK_THREAD(pid, elapsed) \ do \ @@ -108,6 +124,11 @@ clock_t g_preemp_max[CONFIG_SMP_NCPUS]; clock_t g_crit_max[CONFIG_SMP_NCPUS]; #endif +#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 +clock_t g_busywait_max[CONFIG_SMP_NCPUS]; +clock_t g_busywait_total[CONFIG_SMP_NCPUS]; +#endif + /**************************************************************************** * Private Functions ****************************************************************************/ @@ -274,6 +295,63 @@ void nxsched_critmon_csection(FAR struct tcb_s *tcb, bool state, } #endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_CSECTION >= 0 */ +/**************************************************************************** + * Name: nxsched_critmon_busywait + * + * Description: + * Called when a thread try to enter critical section（get spinlock） or + * successfully entered cirtical section. + * + * Assumptions: + * - Called before a critical section or within a critical section. + * - Might be called from an interrupt handler. + * + ****************************************************************************/ + +#if CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 +void nxsched_critmon_busywait(bool state, FAR void *caller) +{ + FAR struct tcb_s *tcb = this_task(); + clock_t current = perf_gettime(); + + /* Are we busy waiting for critical section or spinlock? */ + + if (state) + { + /* Waiting... Save the start time. */ + + tcb->busywait_start = current; + tcb->busywait_caller = caller; + } + else + { + /* Entered critical section... Check for the max elapsed time */ + + clock_t elapsed = current - tcb->busywait_start; + int cpu = this_cpu(); + + if (elapsed > tcb->busywait_max) + { + tcb->busywait_max = elapsed; + tcb->busywait_max_caller = tcb->busywait_caller; + CHECK_BUSYWAIT(tcb->pid, elapsed); + } + + /* Check for the global max elapsed time */ + + if (elapsed > g_busywait_max[cpu]) + { + g_busywait_max[cpu] = elapsed; + } + + /* Update thread-level and cpu-level busywait */ + + tcb->busywait_total += elapsed; + g_busywait_total[cpu] += elapsed; + } +} +#endif /* CONFIG_SCHED_CRITMONITOR_MAXTIME_BUSYWAIT >= 0 */ + /**************************************************************************** * Name: nxsched_switch_critmon *
