Sleep time is too long in STM32F4

[tomhepworth]

Description

I am running the Zephyr "Blinky" example on the STM32F4_Discovery-Kit board. Blinky should change the state of the LED every 1 second. However, when running the software I see it takes roughly 2.33 seconds.

08:57:31.2347 [INFO] usart2: [host:   28.16s (+28.07s)|virt:     2.33s (+2.33s)] LED state: ON
08:57:33.5676 [NOISY] gpioPortD.UserLED: LED state changed to False
08:57:33.5677 [INFO] usart2: [host:    30.49s (+2.33s)|virt:     4.67s (+2.33s)] LED state: OFF
08:57:35.9012 [NOISY] gpioPortD.UserLED: LED state changed to True
08:57:35.9012 [INFO] usart2: [host:    32.82s (+2.33s)|virt:        7s (+2.33s)] LED state: ON
08:57:38.2346 [NOISY] gpioPortD.UserLED: LED state changed to False
08:57:38.2347 [INFO] usart2: [host:    35.16s (+2.33s)|virt:     9.33s (+2.33s)] LED state: OFF
08:57:40.5683 [NOISY] gpioPortD.UserLED: LED state changed to True
08:57:40.5683 [INFO] usart2: [host:    37.49s (+2.33s)|virt:    11.67s (+2.33s)] LED state: ON

The main loop is

        while (1) {
                ret = gpio_pin_toggle_dt(&led);
                if (ret < 0) {
                        return 0;
                }

                led_state = !led_state;
                printf("LED state: %s\n", led_state ? "ON" : "OFF");
                k_msleep(SLEEP_TIME_MS);
        }

Where SLEEP_TIME_MS is 1000

Expected behaviour

Roughly 1 second intervals in virtual time between LED state changes. Instead I see ~2 second intervals between state changes.

How to reproduce?

zephyr build cmd

west build -p always -b stm32f4_disco zephyr/samples/basic/blinky

test.resc

:name: STM32F4 Discovery
:description: This script runs Contiki on STM32F4 Discovery.

using sysbus
$name?="STM32F4_Discovery"
mach create $name
machine LoadPlatformDescription @/home/dev/renode_portable/platforms/boards/stm32f4_discovery-kit.repl

cpu PerformanceInMips 125

sysbus LogPeripheralAccess sysbus.gpioPortA
logLevel -1 sysbus.gpioPortD.UserLED
showAnalyzer sysbus.usart2

$bin?=@/home/dev/zephyr/zephyr/build/zephyr/zephyr.elf
sysbus LoadELF $bin

Environment

Please, provide the following information:

• OS: Ubuntu 22.04
• Renode version (with commit SHA). Linux Portable 1.15.3, SHA 03756cb

Additional information

I also tried removing the printf to see the effect on the latency but it was negligible. Removing the sleep entirely also lets the code spin freely, so it seems like it is the sleep that is taking too long and not something else introducing latency.

Do you plan to address this issue and file a PR?

Happy to try and fix once I know the problem. For now I do not know where to start.

[tomhepworth]

Looks like it could be related to zephyrproject-rtos/zephyr#21762

[otavio]

We had a similar issue in STM32G0. In our case, it was because of PWM frequency was too low and not using the CPU frequency as expected.

[tomhepworth]

Hmm ok I am not doing anything involving PWM as far as I know. I tried playing with CONFIG_SYS_CLOCK_TICKS_PER_SEC but no luck.

[otavio]

Take a look if it is not related to the PWM either way, because in our case it was affecting the timers, so changing the frequency over there fixed the issue for us.

[tomhepworth]

Would you mind giving me some more info on how to do this? I am new to this sort of thing :)

[Mes-ser]

Run your emulation, and execute command

machine GetClockSourceInfo

At the top of the list should be 'sysTick' row. Check at what frequency is it set, and compare to the one you use in your example.
You can check frequency of other peripherals too if they use ManagedThread or LimitTimer objects.

To change systick frequency run for eg.

nvic Frequency 3000000

Or I think in "stm32f4.repl' you should see something like this:

nvic: IRQControllers.NVIC @ sysbus 0xE000E000
priorityMask: 0xC0
IRQ -> cpu@0
frequency: xxxxxxxx

[tomhepworth]

Interesting. I saw that the frequency is set in the stm32f4.repl to 72MHz, and setting CONFIG_SYS_CLOCK_TICKS_PER_SEC=72000000 did appear to have an effect.

It seems like the time is much more precisely 2.0 seconds between state changes rather than ~2.3.

I am not quite sure how this stuff plays with each other yet but will keep digging. Thanks :)

[otavio]

In our specific case we had to change the repl file and adjust that to use the proper frequency as specified in the microcontroller datasheet.

See:

nvic0: IRQControllers.NVIC @ sysbus 0xE000E000
    priorityMask: 0xF0
    systickFrequency: 64000000
    IRQ -> cpu0@0

...
timers17: Timers.STM32_Timer @ sysbus 0x40014800
    frequency: 0x3D09000
    initialLimit: 0xffffffff
    ->nvic0@22
...

[tomhepworth]

Thanks I will try it. Weirdly I am struggling to find that value in the data sheet. That is probably a me-problem though!

Edit: I think it is 100MHz. Setting the value there brought the time interval down to ~1.4s

[Mes-ser]

Look at zephyr examples and tests
https://designer.antmicro.com/hardware/devices/stm32f4_disco?demo=blinky
In 'Download Assets' you can find Renode Logs and even resc/repl files which will give good starting point to find where the issue lies.
I just took quick glance at their .repl file and they set systickFrequency to 168MHz

Maybe try with the official image:

sysbus LoadELF @https://zephyr-dashboard.renode.io/zephyr/2f47de60a0a7038eed1bfe11ced16ae51444434e/stm32f4_disco/blinky/blinky.elf

[tomhepworth]

Thanks for your help, I had not seen that online tool yet :)

Setting it to 168MHz fixed the problem:

15:15:21.9733 [NOISY] gpioPortD.UserLED: LED state changed to True
15:15:22.9734 [NOISY] gpioPortD.UserLED: LED state changed to False
15:15:23.9735 [NOISY] gpioPortD.UserLED: LED state changed to True
15:15:24.9736 [NOISY] gpioPortD.UserLED: LED state changed to False
15:15:25.9737 [NOISY] gpioPortD.UserLED: LED state changed to True
15:15:26.9738 [NOISY] gpioPortD.UserLED: LED state changed to False
15:15:27.9739 [NOISY] gpioPortD.UserLED: LED state changed to True
15:15:28.9749 [NOISY] gpioPortD.UserLED: LED state changed to False

I am struggling to find out why this number was chosen though. I cannot see it in the datasheet. The only thing I have found at 168MHz is the AHB bus on one variant of the stm32f4 core.

Edit: I was looking at the wrong datasheet, it looks like this board assumes the core is a STM32F415xx or STM32F417xx where TIM1 has a "Max timer clock" of 168MHz

[Mes-ser]

Quick search on stm site:

STM32F407/417 – 168 MHz CPU/210 DMIPS, up to 1 Mbyte of Flash memory adding Ethernet MAC and camera interface
STM32F405/415 – 168 MHz CPU/210 DMIPS, up to 1 Mbyte of Flash memory with advanced connectivity and encryption

STM32F4-Discovery-kit uses STM32F407 and in DOCS it state:

frequency up to 168 MHz

So we can easily assume they used maximum frequency at which this mcu can operate.

My question will be, why your code doesn't work when you set CONFIG_SYS_CLOCK_TICKS_PER_SEC and systickFrequency to the same value.

[tomhepworth]

Yes, I had mistakenly been using the STM32F411xC/STM32F411xE data sheet.

I just found this:

&rcc {
	clocks = <&pll>;
	clock-frequency = <DT_FREQ_M(168)>;
	ahb-prescaler = <1>;
	apb1-prescaler = <4>;
	apb2-prescaler = <2>;
};

In zephyr/boards/st/stm32f4_disco/stm32f4_disco.dts

So this could be what is causing a discrepancy

https://docs.zephyrproject.org/latest/build/dts/api/bindings/clock/st,stm32-rcc.html

This node is in charge of system clock ('SYSCLK') source selection and controlling
clocks for AHB (Advanced High Performance) and APB (Advanced Peripheral) bus domains.

So perhaps my setting for CONFIG_SYS_CLOCK_TICKS_PER_SEC was being overridden?