STM32: Bad value returned by systick.get_time_since_boot().to_us()

[mihainicolae80]

Hi,

Calling systick.get_time_since_boot().to_us() will occasionally return a bad value every 50s or so.

HW: STM32 F3 Discovery board
Using Microzig release 0.15.1
Compiling with zig 0.15.2

main.zig:

const std = @import("std");
const microzig = @import("microzig");
const hal = microzig.hal;
const board = microzig.board;
const log = std.log;

pub const microzig_options: microzig.Options = .{
    .logFn = microzig.board.uart_logger.log,
    .cpu = .{
        .ram_vector_table = true,
    },
    .hal = .{ .rcc_clock_config = board.rcc_medium_speed }
};

pub fn init() void
{
    hal.dma.DMA1_Channel4.enable_interrupt();
    board.init();
    board.init_log();

    hal.systick.init() catch {
        @panic("systick init fail");
    };
}

pub fn main() !void
{
    const systick = hal.systick_timer.clock_device() catch {
        @panic("systick_timer clock device");
    };

    var last_us: u64 = systick.get_time_since_boot().to_us();
    while (true)
    {
        const now_us = systick.get_time_since_boot().to_us();

        if (now_us > last_us + 20_000)
        {
            const now2_us = systick.get_time_since_boot().to_us();
            log.info("now_us jump={d}us last_us={d}us now_us={d}us now2_us={d}us", .{now_us - last_us, last_us, now_us, now2_us});
        }
        last_us = now_us;
    }
}

build.zig:

const std = @import("std");
const microzig = @import("microzig");

const MicroBuild = microzig.MicroBuild(.{
    .stm32 = true,
});

pub fn build(b: *std.Build) void {

    const mz_dep = b.dependency("microzig", .{});
    const mb = MicroBuild.init(b, mz_dep) orelse return;

    const firmware = mb.add_firmware(.{
        .name = "firmware",
        .target = mb.ports.stm32.boards.stm32f3discovery,
        .optimize = .Debug,
        .root_source_file = b.path("src/main.zig"),
    });

    mb.install_firmware(firmware, .{});
    mb.install_firmware(firmware, .{ .format = .elf });

    const flash_argv = [_][] const u8 {
        "arm-none-eabi-gdb.exe",
        "-iex",
        "set auto-load safe-path /",
        "--batch", 
        "--quiet",
        "--command=flash.gdb",
    };
    const flash_cmd_step = b.addSystemCommand(&flash_argv);
    flash_cmd_step.step.dependOn(b.getInstallStep());

    const flash_step = b.step("run", "Flash FW to board");
    flash_step.dependOn(&flash_cmd_step.step);
}

Output:

info: ================ STARTING NEW LOGGER ================

info: now_us jump=2785286us last_us=8355833us now_us=11141119us now2_us=8355846us
info: now_us jump=2785285us last_us=30638074us now_us=33423359us now2_us=30638087us
info: now_us jump=2785285us last_us=75202554us now_us=77987839us now2_us=75202567us
info: now_us jump=2785285us last_us=119767034us now_us=122552319us now2_us=119767047us
info: now_us jump=2785286us last_us=125337593us now_us=128122879us now2_us=125337606us
info: now_us jump=2785285us last_us=175472634us now_us=178257919us now2_us=175472647us
info: now_us jump=2785286us last_us=181043193us now_us=183828479us now2_us=181043206us
info: now_us jump=2785285us last_us=231178234us now_us=233963519us now2_us=231178247us
info: now_us jump=2785286us last_us=236748793us now_us=239534079us now2_us=236748806us
info: now_us jump=2785285us last_us=286883834us now_us=289669119us now2_us=286883847us
info: now_us jump=2785286us last_us=292454393us now_us=295239679us now2_us=292454406us
info: now_us jump=2785285us last_us=342589434us now_us=345374719us now2_us=342589447us
info: now_us jump=2785286us last_us=348159993us now_us=350945279us now2_us=348160006us
info: now_us jump=2785285us last_us=398295034us now_us=401080319us now2_us=398295047us
info: now_us jump=2785286us last_us=403865593us now_us=406650879us now2_us=403865606us
info: now_us jump=2785285us last_us=454000634us now_us=456785919us now2_us=454000647us
info: now_us jump=2785286us last_us=459571193us now_us=462356479us now2_us=459571206us

Thanks!

[Grazfather]

Looks like it's a (common) issue where the two registers are read non-atomically and one overflows between reads.

SysTick is running at 6MHz which means 170 ns_per_tick

2^24 * 170 / 1024 / 1000 = 2785285, which is your jump!

Can you please try this patch?

diff --git i/port/stmicro/stm32/src/hals/common/systick.zig w/port/stmicro/stm32/src/hals/common/systick.zig
index 64d4db6d..a802ec4a 100644
--- i/port/stmicro/stm32/src/hals/common/systick.zig
+++ w/port/stmicro/stm32/src/hals/common/systick.zig
@@ -75,10 +75,18 @@ pub fn is_initialized() bool {
 // Low level function to build clock device from it.
 pub fn get_time_since_boot() u64 {
     const reload = systick.LOAD.read().RELOAD;
-    const ticks = @as(u64, @intCast(reload - systick.VAL.read().CURRENT));
-    const all_ticks = @as(u64, @intCast(microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire))) << 24 | ticks;
-    const ns = all_ticks * ns_per_ticks;
-    return ns >> 10;

+    while (true) {
+        const high = microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire);
+        const ticks = @as(u64, @intCast(reload - systick.VAL.read().CURRENT));
+        if (microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire) == high) {
+            const all_ticks = (@as(u64, high) << 24) | ticks;
+            const ns = all_ticks * ns_per_ticks;
+            return ns >> 10;
+        }
+    }
 }

 pub fn SysTick_handler() callconv(.c) void {

[Grazfather]

You'll have to change your build.zig.zon to point to a clone of the repo

[mihainicolae80]

Sorry for the delayed reply. Yes, that solves the issue.

I needed to make a few changes to the patch, as git was complaining about some corrupted lines

diff --git i/port/stmicro/stm32/src/hals/common/systick.zig w/port/stmicro/stm32/src/hals/common/systick.zig
index 64d4db6d..a802ec4a 100644
--- i/port/stmicro/stm32/src/hals/common/systick.zig
+++ w/port/stmicro/stm32/src/hals/common/systick.zig
@@ -75,10 +75,15 @@ pub fn is_initialized() bool {
 // Low level function to build clock device from it.
 pub fn get_time_since_boot() u64 {
     const reload = systick.LOAD.read().RELOAD;
-    const ticks = @as(u64, @intCast(reload - systick.VAL.read().CURRENT));
-    const all_ticks = @as(u64, @intCast(microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire))) << 24 | ticks;
-    const ns = all_ticks * ns_per_ticks;
-    return ns >> 10;
+    while (true) {
+        const high = microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire);
+        const ticks = @as(u64, @intCast(reload - systick.VAL.read().CURRENT));
+        if (microzig.cpu.atomic.load(u32, &accumulated_ticks, .acquire) == high) {
+            const all_ticks = (@as(u64, high) << 24) | ticks;
+            const ns = all_ticks * ns_per_ticks;
+            return ns >> 10;
+        }
+    }
 }
 
 pub fn SysTick_handler() callconv(.c) void {

So the way I understand the problem is that:

• CURRENT is read when it is very close to the 0 value
• CURRENT reaches 0, triggers the systick interrupt handler, and accumulated_ticks is incremented
• accumulated_ticks is then read

So we read CURRENT as part of one systick (RELOAD -> 0) cycle, then read accumulated_ticks as part of the next systick cycle.

I much appreciate the help! The issue can be closed now.