Merge pull request #18795 from benpicco/irq-track

debug_irq_disable: add module to debug time spent in irq_disable

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 */
 

cpu/cortexm_common/include/irq_arch.h

@@ -22,18 +22,45 @@
 #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
  */
-static inline __attribute__((always_inline)) unsigned int irq_disable(void)
+static inline __attribute__((always_inline))
+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;
 }
@@ -41,8 +68,8 @@ static inline __attribute__((always_inline)) unsigned int irq_disable(void)
 /**
  * @brief Enable all maskable interrupts
  */
-static inline __attribute__((always_inline)) __attribute__((used)) unsigned int
-irq_enable(void)
+static inline __attribute__((always_inline)) __attribute__((used))
+unsigned int irq_enable(void)
 {
     unsigned result = __get_PRIMASK();
 
@@ -53,16 +80,35 @@ irq_enable(void)
 /**
  * @brief Restore the state of the IRQ flags
  */
-static inline __attribute__((always_inline)) void irq_restore(
-    unsigned int state)
+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
  */
-static inline __attribute__((always_inline)) bool irq_is_enabled(void)
+static inline __attribute__((always_inline))
+bool irq_is_enabled(void)
 {
     /* so far, all existing Cortex-M are only using the least significant bit
      * in the PRIMARK register. If ever any other bit is used for different
@@ -73,7 +119,8 @@ static inline __attribute__((always_inline)) bool irq_is_enabled(void)
 /**
  * @brief See if the current context is inside an ISR
  */
-static inline __attribute__((always_inline)) bool irq_is_in(void)
+static inline __attribute__((always_inline))
+bool irq_is_in(void)
 {
     return (__get_IPSR() & 0xFF);
 }

sys/Kconfig

@@ -25,6 +25,7 @@ rsource "congure/Kconfig"
 rsource "cpp11-compat/Kconfig"
 rsource "cpp_new_delete/Kconfig"
 rsource "cxx_ctor_guards/Kconfig"
+rsource "debug_irq_disable/Kconfig"
 rsource "div/Kconfig"
 rsource "embunit/Kconfig"
 rsource "entropy_source/Kconfig"

sys/Makefile.dep

@@ -65,6 +65,10 @@ ifneq (,$(filter crc32_fast,$(USEMODULE)))
   USEMODULE += checksum
 endif
 
+ifneq (,$(filter debug_irq_disable,$(USEMODULE)))
+  USEMODULE += fmt
+endif
+
 ifneq (,$(filter eepreg,$(USEMODULE)))
   FEATURES_REQUIRED += periph_eeprom
 endif

sys/debug_irq_disable/Kconfig

@@ -0,0 +1,21 @@
+# Copyright (C) 2022 Benjamin Valentin
+#
+# This file is subject to the terms and conditions of the GNU Lesser
+# General Public License v2.1. See the file LICENSE in the top level
+# directory for more details.
+#
+
+menuconfig MODULE_DEBUG_IRQ_DISABLE
+    bool "Measure IRQ disable durations"
+    depends on TEST_KCONFIG
+    depends on CPU_CORE_CORTEX_M
+    help
+        Print time spent with IRQs disabled
+
+config DEBUG_IRQ_DISABLE_THRESHOLD
+    int "Suppress Threshold"
+    default 1
+    depends on MODULE_DEBUG_IRQ_DISABLE
+    help
+        Threshold (in CPU ticks) below which periods with IRQs disabled are not printed.
+        Use this to prevent *a lot* of output when debugging.

sys/debug_irq_disable/Makefile

@@ -0,0 +1 @@
+include $(RIOTBASE)/Makefile.base

sys/debug_irq_disable/debug_irq_disable.c

@@ -0,0 +1,54 @@
+/*
+ * Copyright (C) 2022 ML!PA Consulting GmbH
+ *
+ * This file is subject to the terms and conditions of the GNU Lesser
+ * General Public License v2.1. See the file LICENSE in the top level
+ * directory for more details.
+ */
+
+/**
+ * @ingroup     debug_irq_disable
+ * @{
+ *
+ * @file
+ * @brief       Helper for debug_irq_disable
+ *
+ * @author      Benjamin Valentin <benjamin.valentin@ml-pa.com>
+ * @}
+ */
+
+#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 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;
+
+    print_str("irq disabled for ");
+    print_u32_dec(ticks);
+    print_str(" ticks in ");
+    print_str(file);
+    print_str(":");
+    print_u32_dec(line);
+    print_str("\n");
+
+    --is_printing;
+}

sys/include/debug_irq_disable.h

@@ -0,0 +1,54 @@
+/*
+ * Copyright (C) 2022 ML!PA Consulting GmbH
+ *
+ * This file is subject to the terms and conditions of the GNU Lesser
+ * General Public License v2.1. See the file LICENSE in the top level
+ * directory for more details.
+ */
+
+/**
+ * @defgroup    debug_irq_disable IRQ Disable Debug helper
+ * @ingroup     sys
+ * @brief       Debug time spent with IRQ disabled
+ * @{
+ *
+ * @file
+ *
+ * @author      Benjamin Valentin <benjamin.valentin@ml-pa.com>
+ */
+
+#ifndef DEBUG_IRQ_DISABLE_H
+#define DEBUG_IRQ_DISABLE_H
+
+#include <stdint.h>
+
+#ifdef __cplusplus
+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
+ *
+ * @param[in] file  file where irq_restore() was called
+ * @param[in] line  line where irq_restore() was called
+ * @param[in] ticks CPU ticks spent with IRQ disabled
+ */
+void debug_irq_disable_print(const char *file, unsigned line, uint32_t ticks);
+
+#ifdef __cplusplus
+}
+#endif
+
+/** @} */
+#endif /* DEBUG_IRQ_DISABLE_H */