Potential problem in TIMG0 as `embassy-time` source

[ProfFan]

I discovered today when debugging a strange timing issue that sometimes I get very large and inconsistent GPIO interrupt latencies:

2024-02-20T17:48:15.207831Z DEBUG magic_loc_central: IMU interval: 1007 us
2024-02-20T17:48:15.208901Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18962370, accel: [64808, 4233, 4502], gyro: [9, 65530, 15] }
2024-02-20T17:48:15.208935Z DEBUG magic_loc_central: IMU interval: 994 us
2024-02-20T17:48:15.210035Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18964365, accel: [64845, 4229, 4490], gyro: [10, 65530, 15] }
2024-02-20T17:48:15.210070Z DEBUG magic_loc_central: IMU interval: 1995 us
2024-02-20T17:48:15.210077Z ERROR magic_loc_central: IMU interval too large: 1995 us
2024-02-20T17:48:15.211301Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18965652, accel: [64808, 4236, 4501], gyro: [9, 65532, 13] }
2024-02-20T17:48:15.211335Z DEBUG magic_loc_central: IMU interval: 1287 us
2024-02-20T17:48:15.212597Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18966404, accel: [64827, 4238, 4495], gyro: [10, 65530, 15] }
2024-02-20T17:48:15.212631Z DEBUG magic_loc_central: IMU interval: 752 us
2024-02-20T17:48:15.213671Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18967405, accel: [64825, 4212, 4519], gyro: [10, 65530, 14] }
2024-02-20T17:48:15.213705Z DEBUG magic_loc_central: IMU interval: 1001 us
2024-02-20T17:48:15.215003Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18968349, accel: [64823, 4239, 4508], gyro: [9, 65531, 14] }
2024-02-20T17:48:15.215038Z DEBUG magic_loc_central: IMU interval: 944 us
2024-02-20T17:48:15.215965Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18969229, accel: [64823, 4225, 4503], gyro: [10, 65530, 16] }
2024-02-20T17:48:15.215988Z DEBUG magic_loc_central: IMU interval: 880 us
2024-02-20T17:48:15.217289Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18970425, accel: [64816, 4211, 4488], gyro: [10, 65530, 15] }
2024-02-20T17:48:15.217311Z DEBUG magic_loc_central: IMU interval: 1196 us
2024-02-20T17:48:15.218465Z DEBUG magic_loc_central: Decoded packet from 0: ImuReport { tag_addr: 1, system_ts: 18972498, accel: [64808, 4249, 4506], gyro: [10, 65529, 14] }

It turns out everything works no problem when I change one line:

    // let timer_group0 = hal::timer::TimerGroup::new(peripherals.TIMG0, &clocks);
    let systick = hal::systimer::SystemTimer::new(peripherals.SYSTIMER);
    embassy::init(&clocks, systick);

    spawner.must_spawn(startup_task(clocks));

[ProfFan]

Since the time values sum to 1 second scale I am guessing that the TIMG0 interrupt is fired for too many times and eats CPU cycles, just a guess though

[MabezDev]

Out of curiosity, could you try the using the generic-queue features of embassy-time, instead of the integrated timers?

[ProfFan]

Out of curiosity, could you try the using the generic-queue features of embassy-time, instead of the integrated timers?

I am using "generic-queue-8" already

[MabezDev]

Do bigger queue values help?

[bjoernQ]

Is it possible to create a minimal-repro of this behavior?

[ProfFan]

Thinking about this, but recently I am too cramped with conference deadlines...

Is it possible to create a minimal-repro of this behavior?

[ProfFan]

Do bigger queue values help?

I can test in a few days

[MabezDev]

Hey @ProfFan, did you get around to digging into this a bit more?

[ProfFan]

@MabezDev Sorry not yet, got too many deadlines on hand now...

[MabezDev]

I'm going to close this for now, @ProfFan please re open when you find out more details :)