cpu/cortexm_common: measure time spent with IRQ disabled

benpicco · benpicco · commit 59a3e613fe02 · 2022-11-24T21:27:20.000+01:00
diff --git a/core/lib/include/irq.h b/core/lib/include/irq.h
@@ -35,6 +35,7 @@ extern "C" {
 #define MAYBE_INLINE
 #endif /* IRQ_API_INLINED */
 
+#ifndef IRQ_API_INLINED
 /**
  * @brief   This function sets the IRQ disable bit in the status register
  *
@@ -89,7 +90,7 @@ MAYBE_INLINE bool irq_is_enabled(void);
  */
 MAYBE_INLINE bool irq_is_in(void);
 
-#ifdef IRQ_API_INLINED
+#else
 #include "irq_arch.h"
 #endif /* IRQ_API_INLINED */
 
diff --git a/cpu/cortexm_common/include/irq_arch.h b/cpu/cortexm_common/include/irq_arch.h
@@ -22,11 +22,33 @@
 #include <stdbool.h>
 #include <stdint.h>
 #include "cpu_conf.h"
+#include "kernel_defines.h"
+#include "debug_irq_disable.h"
 
 #ifdef __cplusplus
 extern "C" {
 #endif
 
+/**
+ * @brief   Start SysTick timer to measure time spent with IRQ disabled
+ */
+static inline void _irq_debug_start_count(void)
+{
+    SysTick->VAL  = 0;
+    SysTick->LOAD = SysTick_LOAD_RELOAD_Msk;
+    SysTick->CTRL = SysTick_CTRL_CLKSOURCE_Msk | SysTick_CTRL_ENABLE_Msk;
+}
+
+/**
+ * @brief   Stop SysTick timer, return time spent with IRQ disabled
+ */
+static inline uint32_t _irq_debug_stop_count(void)
+{
+    uint32_t ticks = SysTick_LOAD_RELOAD_Msk - SysTick->VAL;
+    SysTick->CTRL = 0;
+    return ticks;
+}
+
 /**
  * @brief Disable all maskable interrupts
  */
@@ -35,6 +57,10 @@ unsigned int irq_disable(void)
 {
     uint32_t mask = __get_PRIMASK();
 
+    if ((mask == 0) && IS_USED(MODULE_DEBUG_IRQ_DISABLE)) {
+        _irq_debug_start_count();
+    }
+
     __disable_irq();
     return mask;
 }
@@ -55,10 +81,28 @@ unsigned int irq_enable(void)
  * @brief Restore the state of the IRQ flags
  */
 static inline __attribute__((always_inline))
+#if !IS_USED(MODULE_DEBUG_IRQ_DISABLE)
 void irq_restore(unsigned int state)
 {
     __set_PRIMASK(state);
 }
+#else
+void _irq_restore(unsigned int state, const char *file, unsigned line)
+{
+    uint32_t ticks = 0;
+
+    if (state == 0) {
+        ticks = _irq_debug_stop_count();
+    }
+
+    __set_PRIMASK(state);
+
+    if (ticks) {
+        debug_irq_disable_print(file, line, ticks);
+    }
+}
+#define irq_restore(state) _irq_restore(state, __FILE__, __LINE__);
+#endif /* MODULE_DEBUG_IRQ_DISABLE */
 
 /**
  * @brief See if IRQs are currently enabled
diff --git a/sys/debug_irq_disable/debug_irq_disable.c b/sys/debug_irq_disable/debug_irq_disable.c
@@ -19,17 +19,28 @@
 
 #include <stdbool.h>
 #include "fmt.h"
+#include "debug_irq_disable.h"
 
 void debug_irq_disable_print(const char *file, unsigned line, uint32_t ticks)
 {
-    static bool is_printing;
+    static unsigned is_printing;
+    static unsigned init_skip = 10;
+
+    /* if we try to print before libc is initialized, we will hard fault */
+    if (init_skip && --init_skip) {
+        return;
+    }
 
     if (is_printing) {
         return;
     }
 
+    if (ticks < CONFIG_DEBUG_IRQ_DISABLE_THRESHOLD) {
+        return;
+    }
+
     /* prevent infinite recursion if stdio driver uses irq_disable()  */
-    is_printing = true;
+    ++is_printing;
 
     print_str("irq disabled for ");
     print_u32_dec(ticks);
@@ -39,5 +50,5 @@ void debug_irq_disable_print(const char *file, unsigned line, uint32_t ticks)
     print_u32_dec(line);
     print_str("\n");
 
-    is_printing = false;
+    --is_printing;
 }
diff --git a/sys/include/debug_irq_disable.h b/sys/include/debug_irq_disable.h
@@ -26,6 +26,16 @@
 extern "C" {
 #endif
 
+/**
+ * @brief Threshold (in CPU ticks) below which periods with IRQs
+ *        disabled are not printed.
+ *
+ *        Use this to prevent *a lot* of output when debugging.
+ */
+#ifndef CONFIG_DEBUG_IRQ_DISABLE_THRESHOLD
+#define CONFIG_DEBUG_IRQ_DISABLE_THRESHOLD  (1)
+#endif
+
 /**
  * @brief   Print time spent with IRQ disabled
  * @internal
