Tock: [Bug] Incorrect VirtualMuxAlarm implementation

[gendx]

Context

When setting an alarm with VirtualMuxAlarm, a reference point (self.mux.prev) is set along with the alarm.

https://github.com/tock/tock/blob/f30961f2772a0ef5f41e6f1a04843adf51151a3c/capsules/src/virtual_alarm.rs#L84-L95

This prev reference point is then used to decide whether alarms in the mux have expired or not.

https://github.com/tock/tock/blob/f30961f2772a0ef5f41e6f1a04843adf51151a3c/capsules/src/virtual_alarm.rs#L149

Problem

The problem is that inside VirtualMuxAlarm::set_alarm there is no guarantee that cur_alarm >= now. We can be in a situation where an alarm 1 is already set, and by the time we set another alarm 2, alarm 1 is already in the past (but it hasn't fired yet).

> in VirtualMuxAlarm::set_alarm
alarms:       | alarm 1   |      | alarm 2
before:  prev | cur_alarm | now  | when
after:        |           | prev | cur_alarm

In that case, because the new prev is just after alarm 1, the alarm 1 won't be considered as expired next time MuxAlarm::fired is called - it would instead take time for the ticks to wrap-around for the alarm to be considered expired.

This is in particular observable with the Segger RTT debugging on Nordic, which sets a timer very close in the future (100us). By the time other code has run, this can already be in the past.

https://github.com/tock/tock/blob/f30961f2772a0ef5f41e6f1a04843adf51151a3c/capsules/src/segger_rtt.rs#L243

But all capsules using a virtual alarm are affected.

The observable result is that the alarm client (in this case Segger RTT) waits forever (for Segger RTT, kernel debugging & console seem to freeze).

Reproducing the bug

It's easy to reproduce by adding the following check to VirtualAlarmMux::set_alarm on an nRF52840-DK board with USB_DEBUGGING and trace_syscalls enabled. Note that I've already applied the fix from https://github.com/tock/tock/pull/1636.

if enabled > 0 {
    let cur_alarm = self.mux.alarm.get_alarm();
    let now = self.now();
    let prev = self.mux.prev.get();

    if now.wrapping_sub(prev) > cur_alarm.wrapping_sub(prev) {
        panic!("prev = {}, cur_alarm = {}, now = {}");
    }
    ...
}

I'm using the OpenSK app with the following parameters (see deploy.py).

$ ./deploy.py os --board nrf52840_dk
$ ./deploy.py app --debug --panic-console --opensk

And an example of panic is the following.

Kernel panic at <::core::macros::panic macros>:5:
        "prev = 9025, cur_alarm = 9028, now = 9031"

Without the manual panic, the debug output also freezes quite quickly in this setup.

Solutions?

• I think it's incorrect to move prev forward when setting a new alarm. It should only be updated in the MuxAlarm::fired function, where expired alarms are actually all fired.
• This again shows that the "3-way comparison" of 32-bit timestamps is error-prone, as it's complex to implement, hard to understand, hard to know when it's safe to update the reference point, etc. I think that this is another argument towards having truely monotonic (i.e. 64-bit) timestamps in time-related capsules & HILs (as previously discussed in https://groups.google.com/d/msg/tock-dev/CWecIZq7jqg/RrWySQLbBgAJ).

[alevy]

@gendx this is a great summary, thanks!

I think it's incorrect to move prev forward when setting a new alarm. It should only be updated in the MuxAlarm::fired function, where expired alarms are actually all fired.

I, personally, need to think about this more carefully. Which leads me to...

This again shows that the "3-way comparison" of 32-bit timestamps is error-prone, as it's complex to implement, hard to understand, hard to know when it's safe to update the reference point, etc.

Yes, this is 100% my experience. I believe I've fixed timer bugs like these over several iterations in the past few years, and they are incredibly difficult to debug, especially since they often tend to appear at the edge (near wrapping cases), which occur very infrequently.

[phil-levis]

_We can be in a situation where an alarm 1 is already set, and by the time we set another alarm 2, alarm 1 is already in the past (but it hasn't fired yet)._

But this can be a normal occurrence with any finite type. I think your notion of "past" is confused, because a smaller number actually means in the future, due to wraparound. You can go down the RISC-V route and make all counter values 64 bits and hope things never wraparound. So I would rephrase this as "we can't tell if alarm 1 is in the recent past or far future."

But the thing is, this problem isn't new. It's been solved before. Put another way, there are lots of embedded systems out there that don't miss alarms and don't use 64-bit types. So how do they do it?

The root problem is the decoupling of when an alarm is request and then when it's processed. I think we discussed this in depth in tock-dev. There are good reasons to have a 64-bit counter in the kernel, but I don't think this one of them. The 64 bit counter will wraparound eventually too -- you may have avoided the problem in practice, but you haven't actually solved it.

[gendx]

I think your notion of "past" is confused, because a smaller number actually means in the future, due to wraparound.

To come back to the bug that I observed, there has been no wraparound (the bug occurred within a second of booting the board, all alarms are set to durations much smaller than the wraparound), so there's no confusion about what is past and future (referring to the notions of "past" and "future" in the real world).

Before going back to lengthy discussions about the time HIL, can we agree that prev should never move forward of any alarm still waiting to fire, to hopefully fix this bug?

Otherwise, Tock doesn't uphold the guarantee that setting an alarm in the future will fire. If there's no such guarantee, all capsules that rely on an alarm are essentially broken. Indeed, capsules do rely on the assumption that it's safe to wait on time::AlarmClient::fire() before resuming execution, and that this will indeed fire (more or less at the right time, but definitely not an wraparound later). This is what happens with the Segger RTT capsule.

The "setting an alarm in the future" part is also a reason why I suggested to have a set_alarm_from_now function in #1521. This could even go down to the chip level where "now" would be checked just before setting up the alarm - to make sure that the timestamp is not already elapsed by the time the hardware timer is set. Indeed, this has the shortcoming that the "now" we're talking about may be a bit later in the future, so the alarm may fire later than expected. But regardless of that, even if the interrupt triggers at the right time, it could also already be "too much in the future" by the time the Tock scheduler handles it.

---

But the thing is, this problem isn't new. It's been solved before. Put another way, there are lots of embedded systems out there that don't miss alarms and don't use 64-bit types. So how do they do it?

That's a good question, but if it was solved in Tock, there wouldn't be this bug.

The 64 bit counter will wraparound eventually too -- you may have avoided the problem in practice, but you haven't actually solved it.

I don't think this argument is relevant. Unless there is an embedded system where the wraparound happens within the lifetime of the device (please let me know if you have a system in mind, but the consensus in the last discussion we had was that 64 bits is always enough), the counter will not eventually wraparound.

If the problem is avoided in practice, I don't see any reason to solve it (at least not in mainline Tock). Of course, it's also unclear whether 64-bit timestamps will be simpler to handle (due to the extra cost of handling overflow interrupts). But solving for solving's sake shouldn't be a reason to pursue complex solutions.

---

I think we should be clear about the expected properties of an alarm, and make sure that these properties are implemented accordingly. Here are some further thoughts.

• There should be some set_alarm_from(now, duration) method, which given a now timestamp (as recorded by the capsule) and a duration to wait for, (1) will fire in a reasonable time frame and (2) not before now + duration. Alternatively, an additional set_alarm_from_now(duration) function will compute now itself for capsules that don't care. But I assume making the former available would be more in line with @alevy's concerns in https://github.com/tock/tock/pull/1521#discussion_r372640321.
• A side note is that passing the pair (now, duration) has the same cost as passing a 64-bit value. I'm not generally against it if it works (after all, simulating 64-bit timestamps with overflow interrupts isn't trivial either), but memory usage shouldn't be the main argument.
• If the now + duration is already elapsed, the implementation may call fire() right away without setting any hardware timer.
• The "reasonable" time frame within which the alarm will fire is TBD, but I don't think this could be a hard number like "before now + duration + N", because that depends on many factors.
  
  
  
  • Maybe the real now when calling it is already past now + duration + N.
  
  
  • Other capsules that are also requesting alarms at the same time. Each capsule has its own processing time, which we don't control. But there could be rules about the order in which alarms are triggered, so that a slow capsule that triggers high-frequency alarms doesn't starve other capsules.
  
  
  • Down to the interrupts in the chip, we may want to delay the alarm a little bit, e.g. when a counter is at N and the alarm is to be set at N+1. This could lead to no interrupt being delivered (see the rules for nRF52840's RTC), violating the guarantee that the alarm will fire. Instead, the chip could set the interrupt at N+2 for example. The client's fire() will then trigger one tick too late, but anyway other operations in Tock between the interrupt and the fire() call may already take multiple ticks. I think it would be wrong though to immediately trigger fire() one tick too early, because that's against the "not before now + duration" rule.
  
  
• As a corollary, it should be clear that capsules that expect real-time properties (e.g. an alarm must fire within N ticks of its timestamp) are not currently supported by Tock - in the sense that the capsule might work if it's alone on the system, but there are no guarantees if it competes with other "slow" capsules.

[gendx]

Note: this bug is a "re-discovery" of what I observed a few months ago already in #1513.

[phil-levis]

@gendx I agree completely with your observation on the bug. I was disagreeing with your generalization and conclusions from it. In particular,

_If the problem is avoided in practice, I don't see any reason to solve it (at least not in mainline Tock). Of course, it's also unclear whether 64-bit timestamps will be simpler to handle (due to the extra cost of handling overflow interrupts). But solving for solving's sake shouldn't be a reason to pursue complex solutions._

They're not complex. They're what everyone else does. From a systems standpoint, I'd argue it's always better to solve the problem in essence -- you solve it in practice when doing so in essence is too expensive/complex.

[JayKickliter]

Dropping in to report that I have run into this bug in the real-world while bringing up Tock on a new nRF52-based platform.

This userland app prints (via RTT) Loop 1 once and delay_ms() never returns.

#include <timer.h>

int
main() {
    int i = 0;
    while (1) {
        printf("Loop %d\n", ++i);
        delay_ms(1000);
    }
    return 0;
}