debug_irq_disable: add module to debug time spent in irq_disable

[benpicco]

Contribution description

When writing code that needs to fulfill some kind of real-time grantees, it is often useful to know how much time was spent with interrupts disabled.

This adds a simple debug module that wraps irq_restore() and uses SysTick to measure the time spent with IRQs disabled on Cortex-M.

Testing procedure

Just add

USEMODULE += debug_irq_disable

to your application.

You might also want to add

CFLAGS +=-fmacro-prefix-map=$(RIOTBASE)/=

2022-10-25 13:40:37,926 # irq disabled for 18 ticks in core/mutex.c:102
2022-10-25 13:40:37,930 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,934 # irq disabled for 141 ticks in core/msg.c:190
2022-10-25 13:40:37,938 # irq disabled for 25 ticks in core/mutex.c:102
2022-10-25 13:40:37,942 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,946 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:37,950 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,954 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,959 # irq disabled for 11349 ticks in sys/evtimer/evtimer.c:184
2022-10-25 13:40:37,964 # irq disabled for 248 ticks in sys/evtimer/evtimer.c:169
2022-10-25 13:40:37,968 # irq disabled for 30 ticks in core/mutex.c:170
2022-10-25 13:40:37,972 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,976 # irq disabled for 117 ticks in core/msg.c:398
2022-10-25 13:40:37,980 # irq disabled for 18 ticks in core/mutex.c:102
2022-10-25 13:40:37,984 # irq disabled for 23 ticks in core/mutex.c:170
2022-10-25 13:40:37,988 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:37,992 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:37,996 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:38,000 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:38,004 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:38,008 # irq disabled for 18 ticks in core/mutex.c:106
2022-10-25 13:40:38,012 # irq disabled for 23 ticks in core/mutex.c:170
2022-10-25 13:40:38,016 # irq disabled for 25 ticks in core/mutex.c:102
2022-10-25 13:40:38,020 # irq disabled for 19 ticks in core/mutex.c:170
2022-10-25 13:40:38,024 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:38,028 # irq disabled for 23 ticks in core/mutex.c:170
2022-10-25 13:40:38,035 # irq disabled for 24 ticks in sys/net/gnrc/network_layer/ipv6/gnrc_ipv6.c:554
2022-10-25 13:40:38,042 # irq disabled for 67 ticks in sys/net/gnrc/network_layer/ipv6/gnrc_ipv6.c:285
2022-10-25 13:40:38,046 # irq disabled for 286 ticks in core/msg.c:121
2022-10-25 13:40:38,050 # irq disabled for 21 ticks in core/thread_flags.c:68
2022-10-25 13:40:38,054 # irq disabled for 40 ticks in sys/event/event.c:67
2022-10-25 13:40:38,058 # irq disabled for 74 ticks in core/msg.c:398
2022-10-25 13:40:38,062 # irq disabled for 26 ticks in core/mutex.c:102
2022-10-25 13:40:38,066 # irq disabled for 30 ticks in core/mutex.c:170
2022-10-25 13:40:38,071 # irq disabled for 27 ticks in sys/event/event.c:67
2022-10-25 13:40:38,074 # irq disabled for 47 ticks in core/msg.c:367
2022-10-25 13:40:38,079 # irq disabled for 118 ticks in core/thread_flags.c:81
2022-10-25 13:40:38,083 # irq disabled for 115 ticks in core/msg.c:391
2022-10-25 13:40:46,679 # irq disabled for 161 ticks in sys/ztimer/core.c:189
2022-10-25 13:40:46,684 # irq disabled for 11610 ticks in sys/ztimer/core.c:120
2022-10-25 13:40:46,688 # irq disabled for 103 ticks in sys/ztimer/core.c:189
2022-10-25 13:40:46,693 # irq disabled for 10943 ticks in sys/ztimer/core.c:120
2022-10-25 13:40:46,698 # irq disabled for 9630 ticks in sys/ztimer/periph_rtt.c:62
2022-10-25 13:40:46,702 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:46,706 # irq disabled for 17 ticks in core/mutex.c:102
2022-10-25 13:40:46,710 # irq disabled for 18 ticks in core/mutex.c:106
2022-10-25 13:40:46,714 # irq disabled for 18 ticks in core/mutex.c:106
2022-10-25 13:40:46,718 # irq disabled for 25 ticks in core/mutex.c:102
2022-10-25 13:40:46,722 # irq disabled for 30 ticks in core/mutex.c:170
2022-10-25 13:40:46,726 # irq disabled for 17 ticks in core/mutex.c:102

Issues/PRs references

[kfessel]

wouldn't this work better if we keep the systick running and store the lock time

and than return reload_mask & ( unlock_time -locktime)

[benpicco]

Why do you think that's better? We'd need an extra variable and start / stop would no longer by symmetric, we'd need an extra function to start the SysTick.

[kfessel]

The way this PR does it is: ether use systick for this xor for something else (e.g.: your countdowntimer)
The way would allow you to have any Initialisation on that systick (counting down or systicking around) and do this and all that needs is static uint32_t

i am not sure if it also would be quicker since these are 3 memory write accesses and mine has 1 read and 1 write for start and this has 1 read and 1 write for stop vs mine has 2 reads.

[benpicco]

The Countdown timer wouldn't run the SysTick continuously either, only when there is a countdown scheduled.
It would be incompatible with this either way, if merged.

And I'm not that concerned about a few instructions here - the UART printouts will ensure that this is purely a debug feature and can't be used for anything performance critical 😉

[jue89]

Nice PR! This seems to be helpful for optimizing IRQ latencies.

[riot-ci]

Murdock results

✔️ PASSED

59a3e61 cpu/cortexm_common: measure time spent with IRQ disabled

Success	Failures	Total	Runtime
117858	0	117858	02h:02m:38s

Artifacts

• Documentation preview

This only reflects a subset of all builds from https://ci-prod.riot-os.org. Please refer to https://ci.riot-os.org for a complete build for now.

[jue89]

ACK.

This module doesn't interfere if it's not explicitly selected.

Diff of FW bins compiled from tests/irq_disable_restore with and without this patch - debug_irq_disable not selected:

--- tests_irq_disable_restore-52aa12bd.bin.hex	2022-11-25 18:22:59.561436017 +0100
+++ tests_irq_disable_restore-59a3e613.bin.hex	2022-11-25 18:23:26.585889500 +0100
@@ -765,8 +765,8 @@
 00002fc0: 1513 1007 1a0c 1206 0b05 0a09 6d61 696e  ............main
 00002fd0: 2829 3a20 5468 6973 2069 7320 5249 4f54  (): This is RIOT
 00002fe0: 2120 2856 6572 7369 6f6e 3a20 3230 3233  ! (Version: 2023
-00002ff0: 2e30 312d 6465 7665 6c2d 3131 352d 6735  .01-devel-115-g5
-00003000: 3261 6131 2d48 4541 4429 006d 6169 6e00  2aa1-HEAD).main.
+00002ff0: 2e30 312d 6465 7665 6c2d 3131 382d 6735  .01-devel-118-g5
+00003000: 3961 3365 2d48 4541 4429 006d 6169 6e00  9a3e-HEAD).main.
 00003010: 2a2a 2a20 5249 4f54 206b 6572 6e65 6c20  *** RIOT kernel 
 00003020: 7061 6e69 633a 0a25 730a 0a00 2a2a 2a20  panic:.%s...*** 
 00003030: 6861 6c74 6564 2e0a 0073 6368 6564 756c  halted...schedul

It's a useful tool to get a feeling how long IRQs are disabled and support debugging of high IRQ latencies.