Skip to content

Commit 5fc4dfe

Browse files
authored
hiffy: only reset timer if it has elapsed (#2530)
Issue #2528 describes a bug in Hiffy introduced by the change to make Hiffy callable over the management network directly, rather than through `udprpc` (PR #2466). The bug results in Hiffy calls via a debug probe timing out while the system is connected to a management network. As I described in [this comment][1], @jamesmunns and I determined that this occurs due to a combination of two factors: First, the top of the `main()` loop in `task-hiffy` always begins by unconditionally advancing the deadline by `sleep_ms` and calling `sys_set_timer()` with the new deadline. Second, the check for whether `HIFFY_KICK` was set by the probe is *conditional on whether the timer notification has fired*. If hiffy was only notified by the timer, this would be fine; the previous timeout has elapsed so we should advance the timer. However, if Hiffy has been notified by the `net` task's `SOCKET` notification, we will set the timer forwards, but we will _not_ check `HIFFY_KICK`, meaning any kick delivered by the debug probe is missed. While debugging, we noticed that a large number of seemingly spurious notifications were being posted to hiffy by the `net` task. When the management network is connected, these spurious notifications are posted more frequently than the timer, meaning that the timer *never* completes, and `HIFFY_KICK` is never checked. This commit fixes the bug by changing `task-hiffy`'s main loop in two main ways. First, we _always_ check the value of `HIFFY_KICK`, regardless of which notification woke us. This change alone is sufficient to fix the bug, as I demonstrated in [this comment][2]. This probably also reduces the latency of the `net` Hiffy RPC, as it kicks execution by _also_ setting `HIFFY_KICK`, and then waiting for the timer to fire to start execution. This way, we no longer need to wait for the timer. In addition, I have also changed the `main()` loop so that the timer is only reset at the end of the loop, if it has actually fired. This way, no matter how often the `net` task notifies us, the timer will always fire before being reset. I believe that either of these changes would be sufficient to fix the bug, but fixing both of them makes the behavior closer to what we would expect. To demonstrate that it works, here's me flashing `mb-1-sp` (the system on which the bug was first encountered) with an image from this branch, and calling Hiffy both via the probe (using `humility net ip`, which uses Hiffy), and then over the network. Note that they both work fine now. Yay! ```console eliza@jeeves ~ $ export HUMILITY_ARCHIVE="$HOME/build-cosmo-b-dev-image-default.hiffy-kickme.zip" eliza@jeeves ~ $ pfexec /staff/eliza/humility -t mb-1-sp flash humility: WARNING: archive in environment variable overriding archive in environment file humility: attached to archive humility: attaching with chip set to "STM32H753ZITx" humility: attached to 1fc9:0143:ISS1EG0OBG2HT via CMSIS-DAP humility: flash/archive mismatch; reflashing humility: skipping measurement token handoff humility: auxiliary flash data is already loaded in slot 0; skipping programming humility: done with auxiliary flash humility: flashing done eliza@jeeves ~ $ pfexec /staff/eliza/humility -t mb-1-sp net ip humility: WARNING: archive in environment variable overriding archive in environment file humility: attached to 1fc9:0143:ISS1EG0OBG2HT via CMSIS-DAP MAC address: a8:40:25:04:11:c5 IPv6 address: fe80::aa40:25ff:fe04:11c5 eliza@jeeves ~ $ /staff/eliza/humility --ip fe80::aa40:25ff:fe04:11c5%e1000g0 hiffy -c Sequencer.get_state humility: connecting to fe80::aa40:25ff:fe04:11c5%2 Sequencer.get_state() => A0PlusHP eliza@jeeves ~ $ ``` This fixes #2528. Note that the spurious notifications from the `net` task are *not* fixed by this change, but Hiffy can now behave directly despite them. We need to determine why we're getting so many notifications while the recv queue is empty as well, but this commit fixes the bug. I've opened #2532 to track investigating the spurious notifications. [1]: #2528 (comment) [2]: #2528 (comment)
1 parent c0e6e8b commit 5fc4dfe

1 file changed

Lines changed: 47 additions & 15 deletions

File tree

task/hiffy/src/main.rs

Lines changed: 47 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -195,13 +195,13 @@ fn main() -> ! {
195195
#[cfg(feature = "net")]
196196
let mut net_state = net::State::new();
197197

198+
// Set the initial timer deadline.
199+
set_timer(sleep_ms);
198200
loop {
199-
// Sleep until either the timer expires or we receive a notification
200-
// from the `net` task indicating that it's ready for us.
201-
let deadline = sys_get_timer().now.saturating_add(sleep_ms);
202201
HIFFY_READY.store(1, Ordering::Relaxed);
203-
sys_set_timer(Some(deadline), notifications::TIMER_MASK);
204202

203+
// Sleep until either the timer expires or we receive a notification
204+
// from the `net` task indicating that it's ready for us.
205205
#[cfg(feature = "net")]
206206
let bits = notifications::SOCKET_MASK | notifications::TIMER_MASK;
207207
#[cfg(not(feature = "net"))]
@@ -215,25 +215,48 @@ fn main() -> ! {
215215
net_state.check_net();
216216
}
217217

218-
if notif.has_timer_fired(notifications::TIMER_MASK) {
219-
// Humility writes `1` to `HIFFY_KICK`
220-
if HIFFY_KICK.load(Ordering::Acquire) == 0 {
218+
//
219+
// We shall reset the timer under either of the following conditions:
220+
//
221+
// 1. The previous deadline has elapsed (naturally), so that we
222+
// can continue polling. This is the condition we check here.
223+
// 2. We have been kicked and executed something, and the sleep
224+
// duration has been reset. This is checked below.
225+
//
226+
// If the "net" feature is *not* enabled, this sounds suspiciously
227+
// similar to just resetting the timer on every iteration of the loop,
228+
// and in fact, it may as well be. However, if the "net" feature *is*
229+
// enabled, we do not wish to reset the timer every time we wake up,
230+
// as this means that notifications from `net` would reset the timer
231+
// even if it has not yet completed. This way, we only reset the timer
232+
// when we are woken by the timer *or* if we were kicked by a network
233+
// RPC, rather than resetting it any time we receive a packet (or on
234+
// spurious notifications from any source).
235+
//
236+
let mut should_reset_timer =
237+
notif.has_timer_fired(notifications::TIMER_MASK);
238+
239+
// Humility writes `1` to `HIFFY_KICK`
240+
if HIFFY_KICK.load(Ordering::Acquire) == 0 {
241+
// If we were woken by the timer, rather than the net task,
242+
// increment the number of times we have slept without being
243+
// kicked.
244+
if should_reset_timer {
221245
sleeps += 1;
222-
223-
// Exponentially backoff our sleep value, but no more than 250ms
224-
if sleeps == 10 {
225-
sleep_ms = core::cmp::min(sleep_ms * 10, 250);
226-
sleeps = 0;
227-
}
228-
229-
continue;
230246
}
231247

248+
// Exponentially backoff our sleep value, but no more than 250ms
249+
if sleeps == 10 {
250+
sleep_ms = core::cmp::min(sleep_ms * 10, 250);
251+
sleeps = 0;
252+
}
253+
} else {
232254
//
233255
// Whenever we have been kicked, we adjust our timeout down to 1ms,
234256
// from which we will exponentially backoff
235257
//
236258
HIFFY_KICK.store(0, Ordering::Release);
259+
should_reset_timer = true;
237260
sleep_ms = 1;
238261
sleeps = 0;
239262

@@ -292,9 +315,18 @@ fn main() -> ! {
292315
}
293316
}
294317
}
318+
319+
if should_reset_timer {
320+
set_timer(sleep_ms);
321+
}
295322
}
296323
}
297324

325+
fn set_timer(sleep_ms: u64) {
326+
let deadline = sys_get_timer().now.saturating_add(sleep_ms);
327+
sys_set_timer(Some(deadline), notifications::TIMER_MASK);
328+
}
329+
298330
/// Converts an array pointer to a shared reference with a particular lifetime
299331
///
300332
/// # Safety

0 commit comments

Comments
 (0)