Furi: count ISR time. Cli: show ISR time in top. (#3751)

* Furi: count ISR time. Cli: show ISR time in top.
* hal: interrupt: macros for interrupt accounting; split FURI_ALWAYS_STATIC_INLINE -> FURI_ALWAYS_INLINE static

Co-authored-by: hedger <hedger@nanode.su>
Co-authored-by: hedger <hedger@users.noreply.github.com>

applications/services/cli/cli_commands.c

@@ -399,8 +399,9 @@ static void cli_command_top(Cli* cli, FuriString* args, void* context) {
 
         uint32_t uptime = tick / furi_kernel_get_tick_frequency();
         printf(
-            "Threads: %zu, Uptime: %luh%lum%lus\r\n",
+            "Threads: %zu, ISR Time: %0.2f%%, Uptime: %luh%lum%lus\r\n",
             furi_thread_list_size(thread_list),
+            (double)furi_thread_list_get_isr_time(thread_list),
             uptime / 60 / 60,
             uptime / 60 % 60,
             uptime % 60);

furi/core/common_defines.h

@@ -29,8 +29,8 @@ extern "C" {
 #define FURI_PACKED __attribute__((packed))
 #endif
 
-#ifndef FURI_ALWAYS_STATIC_INLINE
-#define FURI_ALWAYS_STATIC_INLINE __attribute__((always_inline)) static inline
+#ifndef FURI_ALWAYS_INLINE
+#define FURI_ALWAYS_INLINE __attribute__((always_inline)) inline
 #endif
 
 #ifndef FURI_IS_IRQ_MASKED

furi/core/thread_list.c

@@ -1,6 +1,8 @@
 #include "thread_list.h"
 #include "check.h"
 
+#include <furi_hal_interrupt.h>
+
 #include <m-array.h>
 #include <m-dict.h>
 
@@ -23,6 +25,8 @@ struct FuriThreadList {
     FuriThreadListItemDict_t search;
     uint32_t runtime_previous;
     uint32_t runtime_current;
+    uint32_t isr_previous;
+    uint32_t isr_current;
 };
 
 FuriThreadList* furi_thread_list_alloc(void) {
@@ -85,7 +89,10 @@ void furi_thread_list_process(FuriThreadList* instance, uint32_t runtime, uint32
     instance->runtime_previous = instance->runtime_current;
     instance->runtime_current = runtime;
 
-    uint32_t runtime_counter = instance->runtime_current - instance->runtime_previous;
+    instance->isr_previous = instance->isr_current;
+    instance->isr_current = furi_hal_interrupt_get_time_in_isr_total();
+
+    const uint32_t runtime_counter = instance->runtime_current - instance->runtime_previous;
 
     FuriThreadListItemArray_it_t it;
     FuriThreadListItemArray_it(it, instance->items);
@@ -108,3 +115,10 @@ void furi_thread_list_process(FuriThreadList* instance, uint32_t runtime, uint32
         }
     }
 }
+
+float furi_thread_list_get_isr_time(FuriThreadList* instance) {
+    const uint32_t runtime_counter = instance->runtime_current - instance->runtime_previous;
+    const uint32_t isr_counter = instance->isr_current - instance->isr_previous;
+
+    return (float)isr_counter / (float)runtime_counter;
+}

furi/core/thread_list.h

@@ -76,6 +76,14 @@ FuriThreadListItem* furi_thread_list_get_or_insert(FuriThreadList* instance, Fur
  */
 void furi_thread_list_process(FuriThreadList* instance, uint32_t runtime, uint32_t tick);
 
+/** Get percent of time spent in ISR
+ *
+ * @param      instance  The instance
+ *
+ * @return     percent of time spent in ISR
+ */
+float furi_thread_list_get_isr_time(FuriThreadList* instance);
+
 #ifdef __cplusplus
 }
 #endif

targets/f18/api_symbols.csv

@@ -1,5 +1,5 @@
 entry,status,name,type,params
-Version,+,68.0,,
+Version,+,68.1,,
 Header,+,applications/services/bt/bt_service/bt.h,,
 Header,+,applications/services/bt/bt_service/bt_keys_storage.h,,
 Header,+,applications/services/cli/cli.h,,
@@ -1288,6 +1288,7 @@ Function,+,furi_hal_info_get_api_version,void,"uint16_t*, uint16_t*"
 Function,-,furi_hal_init,void,
 Function,-,furi_hal_init_early,void,
 Function,+,furi_hal_interrupt_get_name,const char*,uint8_t
+Function,+,furi_hal_interrupt_get_time_in_isr_total,uint32_t,
 Function,-,furi_hal_interrupt_init,void,
 Function,+,furi_hal_interrupt_set_isr,void,"FuriHalInterruptId, FuriHalInterruptISR, void*"
 Function,+,furi_hal_interrupt_set_isr_ex,void,"FuriHalInterruptId, FuriHalInterruptPriority, FuriHalInterruptISR, void*"
@@ -1633,6 +1634,7 @@ Function,+,furi_thread_join,_Bool,FuriThread*
 Function,+,furi_thread_list_alloc,FuriThreadList*,
 Function,+,furi_thread_list_free,void,FuriThreadList*
 Function,+,furi_thread_list_get_at,FuriThreadListItem*,"FuriThreadList*, size_t"
+Function,+,furi_thread_list_get_isr_time,float,FuriThreadList*
 Function,+,furi_thread_list_get_or_insert,FuriThreadListItem*,"FuriThreadList*, FuriThread*"
 Function,+,furi_thread_list_process,void,"FuriThreadList*, uint32_t, uint32_t"
 Function,+,furi_thread_list_size,size_t,FuriThreadList*

targets/f7/api_symbols.csv

@@ -1,5 +1,5 @@
 entry,status,name,type,params
-Version,+,68.0,,
+Version,+,68.1,,
 Header,+,applications/drivers/subghz/cc1101_ext/cc1101_ext_interconnect.h,,
 Header,+,applications/services/bt/bt_service/bt.h,,
 Header,+,applications/services/bt/bt_service/bt_keys_storage.h,,
@@ -1413,6 +1413,7 @@ Function,+,furi_hal_infrared_set_tx_output,void,FuriHalInfraredTxPin
 Function,-,furi_hal_init,void,
 Function,-,furi_hal_init_early,void,
 Function,+,furi_hal_interrupt_get_name,const char*,uint8_t
+Function,+,furi_hal_interrupt_get_time_in_isr_total,uint32_t,
 Function,-,furi_hal_interrupt_init,void,
 Function,+,furi_hal_interrupt_set_isr,void,"FuriHalInterruptId, FuriHalInterruptISR, void*"
 Function,+,furi_hal_interrupt_set_isr_ex,void,"FuriHalInterruptId, FuriHalInterruptPriority, FuriHalInterruptISR, void*"
@@ -1847,6 +1848,7 @@ Function,+,furi_thread_join,_Bool,FuriThread*
 Function,+,furi_thread_list_alloc,FuriThreadList*,
 Function,+,furi_thread_list_free,void,FuriThreadList*
 Function,+,furi_thread_list_get_at,FuriThreadListItem*,"FuriThreadList*, size_t"
+Function,+,furi_thread_list_get_isr_time,float,FuriThreadList*
 Function,+,furi_thread_list_get_or_insert,FuriThreadListItem*,"FuriThreadList*, FuriThread*"
 Function,+,furi_thread_list_process,void,"FuriThreadList*, uint32_t, uint32_t"
 Function,+,furi_thread_list_size,size_t,FuriThreadList*

targets/f7/furi_hal/furi_hal_gpio.c

@@ -249,7 +249,7 @@ void furi_hal_gpio_remove_int_callback(const GpioPin* gpio) {
     FURI_CRITICAL_EXIT();
 }
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_gpio_int_call(uint16_t pin_num) {
+FURI_ALWAYS_INLINE static void furi_hal_gpio_int_call(uint16_t pin_num) {
     if(gpio_interrupt[pin_num].callback) {
         gpio_interrupt[pin_num].callback(gpio_interrupt[pin_num].context);
     }

targets/f7/furi_hal/furi_hal_interrupt.c

@@ -13,12 +13,22 @@
 
 #define FURI_HAL_INTERRUPT_DEFAULT_PRIORITY (configLIBRARY_MAX_SYSCALL_INTERRUPT_PRIORITY + 5)
 
+#define FURI_HAL_INTERRUPT_ACCOUNT_START() const uint32_t _isr_start = DWT->CYCCNT;
+#define FURI_HAL_INTERRUPT_ACCOUNT_END()                    \
+    const uint32_t _time_in_isr = DWT->CYCCNT - _isr_start; \
+    furi_hal_interrupt.counter_time_in_isr_total += _time_in_isr;
+
 typedef struct {
     FuriHalInterruptISR isr;
     void* context;
 } FuriHalInterruptISRPair;
 
-FuriHalInterruptISRPair furi_hal_interrupt_isr[FuriHalInterruptIdMax] = {0};
+typedef struct {
+    FuriHalInterruptISRPair isr[FuriHalInterruptIdMax];
+    uint32_t counter_time_in_isr_total;
+} FuriHalIterrupt;
+
+static FuriHalIterrupt furi_hal_interrupt = {};
 
 const IRQn_Type furi_hal_interrupt_irqn[FuriHalInterruptIdMax] = {
     // TIM1, TIM16, TIM17
@@ -67,32 +77,36 @@ const IRQn_Type furi_hal_interrupt_irqn[FuriHalInterruptIdMax] = {
     [FuriHalInterruptIdLpUart1] = LPUART1_IRQn,
 };
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_interrupt_call(FuriHalInterruptId index) {
-    furi_check(furi_hal_interrupt_isr[index].isr);
-    furi_hal_interrupt_isr[index].isr(furi_hal_interrupt_isr[index].context);
+FURI_ALWAYS_INLINE static void furi_hal_interrupt_call(FuriHalInterruptId index) {
+    const FuriHalInterruptISRPair* isr_descr = &furi_hal_interrupt.isr[index];
+    furi_check(isr_descr->isr);
+
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
+    isr_descr->isr(isr_descr->context);
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 }
 
-FURI_ALWAYS_STATIC_INLINE void
+FURI_ALWAYS_INLINE static void
     furi_hal_interrupt_enable(FuriHalInterruptId index, uint16_t priority) {
     NVIC_SetPriority(
         furi_hal_interrupt_irqn[index],
         NVIC_EncodePriority(NVIC_GetPriorityGrouping(), priority, 0));
     NVIC_EnableIRQ(furi_hal_interrupt_irqn[index]);
 }
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_interrupt_clear_pending(FuriHalInterruptId index) {
+FURI_ALWAYS_INLINE static void furi_hal_interrupt_clear_pending(FuriHalInterruptId index) {
     NVIC_ClearPendingIRQ(furi_hal_interrupt_irqn[index]);
 }
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_interrupt_get_pending(FuriHalInterruptId index) {
+FURI_ALWAYS_INLINE static void furi_hal_interrupt_get_pending(FuriHalInterruptId index) {
     NVIC_GetPendingIRQ(furi_hal_interrupt_irqn[index]);
 }
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_interrupt_set_pending(FuriHalInterruptId index) {
+FURI_ALWAYS_INLINE static void furi_hal_interrupt_set_pending(FuriHalInterruptId index) {
     NVIC_SetPendingIRQ(furi_hal_interrupt_irqn[index]);
 }
 
-FURI_ALWAYS_STATIC_INLINE void furi_hal_interrupt_disable(FuriHalInterruptId index) {
+FURI_ALWAYS_INLINE static void furi_hal_interrupt_disable(FuriHalInterruptId index) {
     NVIC_DisableIRQ(furi_hal_interrupt_irqn[index]);
 }
 
@@ -137,17 +151,18 @@ void furi_hal_interrupt_set_isr_ex(
 
     uint16_t real_priority = FURI_HAL_INTERRUPT_DEFAULT_PRIORITY - priority;
 
+    FuriHalInterruptISRPair* isr_descr = &furi_hal_interrupt.isr[index];
     if(isr) {
         // Pre ISR set
-        furi_check(furi_hal_interrupt_isr[index].isr == NULL);
+        furi_check(isr_descr->isr == NULL);
     } else {
         // Pre ISR clear
         furi_hal_interrupt_disable(index);
         furi_hal_interrupt_clear_pending(index);
     }
 
-    furi_hal_interrupt_isr[index].isr = isr;
-    furi_hal_interrupt_isr[index].context = context;
+    isr_descr->isr = isr;
+    isr_descr->context = context;
     __DMB();
 
     if(isr) {
@@ -304,27 +319,37 @@ extern void HW_IPCC_Tx_Handler(void);
 extern void HW_IPCC_Rx_Handler(void);
 
 void SysTick_Handler(void) {
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
     furi_hal_os_tick();
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 }
 
 void USB_LP_IRQHandler(void) {
 #ifndef FURI_RAM_EXEC
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
     usbd_poll(&udev);
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 #endif
 }
 
 void USB_HP_IRQHandler(void) { //-V524
 #ifndef FURI_RAM_EXEC
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
     usbd_poll(&udev);
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 #endif
 }
 
 void IPCC_C1_TX_IRQHandler(void) {
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
     HW_IPCC_Tx_Handler();
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 }
 
 void IPCC_C1_RX_IRQHandler(void) {
+    FURI_HAL_INTERRUPT_ACCOUNT_START();
     HW_IPCC_Rx_Handler();
+    FURI_HAL_INTERRUPT_ACCOUNT_END();
 }
 
 void FPU_IRQHandler(void) {
@@ -499,3 +524,7 @@ const char* furi_hal_interrupt_get_name(uint8_t exception_number) {
         return NULL;
     }
 }
+
+uint32_t furi_hal_interrupt_get_time_in_isr_total(void) {
+    return furi_hal_interrupt.counter_time_in_isr_total;
+}

targets/f7/furi_hal/furi_hal_interrupt.h

@@ -118,6 +118,12 @@ void furi_hal_interrupt_set_isr_ex(
  */
 const char* furi_hal_interrupt_get_name(uint8_t exception_number);
 
+/** Get total time(in CPU clocks) spent in ISR
+ *
+ * @return     total time in CPU clocks
+ */
+uint32_t furi_hal_interrupt_get_time_in_isr_total(void);
+
 #ifdef __cplusplus
 }
 #endif