Tock: delay_ms (1) blocks the process (and maybe the whole alarm system) on stm boards

[alexandruradovici]

Using delay_ms with 0 or 1 will block the running process (and I think it might lock any other alarm, as this will be considered the first one) on stm boards (and maybe others).

I tried to do some debugging, it seems that yield never returns. The alarm driver sets the timeout to a tick that is before the cnt counter, so the interrupt never fires (might fire after overflow).

A quick fix is in capsules/src/alarm.rs, adding a few extra ticks if data is less then now(), but this is not really generic. Maybe the underlying alarm should fire immediately if the tick is below (and very close to) the current counter?

rust let time = if data > self.alarm.now() as usize { data } else { (self.alarm.now () + 10) as usize };

Application code is
c int main(void) { putnstr_async(hello, sizeof(hello), nop, NULL); int i = 0; while (1) { i = i + 1; snprintf (hello, sizeof (hello)-1, "%d\r\n", i); putnstr_async(hello, strlen(hello), nop, NULL); if ((i / 100)%2 == 0) { led_off(0); } else { led_on(0); } delay_ms (1); // execution does not arrive here } return 0; }

[alevy]

Maybe the underlying alarm should fire immediately if the tick is below (and very close to) the current counter?

Indeed, this is what the SAM4L does (while also allowing for time the chip requires to sync with asynchronous timer):

https://github.com/tock/tock/blob/master/chips/sam4l/src/ast.rs#L321

This is the right strategy

[alevy]

Nice catch!

[alexandruradovici]

I am getting some very interesting behavior. I modified the stm32f4xx code with the following:

(ALARM0_SYNC_TICS is set to 8, tried several values with same result)

rust let now = self.registers.cnt.get (); if tics.wrapping_sub(now <= ALARM0_SYNC_TICS { tics = now.wrapping_add(ALARM0_SYNC_TICS); }
When tics is smaller than now, wrapping_sub will return 4294967294. I assume this is the expected result (it is the same in the rust playground). Obviously the if does not go through and tics is set to a value lower than now.

I tried the second approach:

rust let now = self.registers.cnt.get(); let itics: i64 = i64::from(tics); let inow: i64 = i64::from(now); debug!("{}", inow - itics); if itics <= inow && i64::abs(inow - itics) as u32 <= ALARM0_SYNC_TICS { tics = now.wrapping_add(ALARM0_SYNC_TICS); }
It works now, tics is set to a value higher than now, the problem is that the alarm gets rescheduled, as virtual_alarm gets a false from the has_expired function (which uses wrapped_sub).

The only way I could make it work is by using the second approach and adding the following line in alarm.rs:

rust let time = if data > self.alarm.now() as usize { data } else { (self.alarm.now () + 10) as usize };

I'm not sure I understand the reason behind has_expired, I think the problem is there. Did anyone test the delay_ms (0) and delay_me (1) on the saml4?

[gendx]

There are several bugs related to alarms. See also #1651 and #1513.

[alevy]

I did some debugging on Hail (which is SAM4L-based). My results may be slightly different that what you're seeing a different platform with a different CPU clock speed and timer frequency.

Anyway, I believe the fault actually lies in the C userland timer library (likely in the Rust one as well, but I haven't looked at it). In particular, it appears that the kernel is behaving correctly given the values that arrive in the Alarm system-call driver, which indeed result in an expiration value _earlier than_ the current time in some cases (in my case it's on the second iteration through the loop with delay_ms(0)).

What's going on is that the conversion from an interval (0 ms from now) to a concrete timestamp happens in userspace, in the timer_in function in libtock/alarm_timer.c. To perform the conversion, the library needs to perform two system calls: one to get the underlying clock frequency (to convert from milliseconds to tics) and another to get the current time in tics.

Only then does it subscribe for a callback and set the timer (another two system calls).

On the SAM4L, running at 48MHz, a round-trip system call takes on the order of 20-50uS. The AST is running at 16KHz, meaning a tic takes 62.5uS to elapse.

So... there are 1.5 system calls between obtaining the current time in tics and actually setting sending the new alarm to the kernel. And those 1.5 system calls can easily take more than a single timer tic to complete! If we start wanting to set the alarm to the current time, by the time those 1.5 system calls elapsed the "current time" is likely to have ticked forward.

Note that, on the SAM4L, I cannot reproduce a problem with delay_ms(1), which makes sense because it would take on the order of 20 system calls for a whole millisecond to elapse.

Now as to how to fix this... that's a question for tomorrow...

[gendx]

Now as to how to fix this... that's a question for tomorrow...

I think this is a very relevant problem to solve. Looking at the alarm redesign proposal, I think it can be solved by the new set_alarm interface taking as input both the desired timestamp and the last known "now" timestamp.

fn set_alarm(&self, now: Self::Ticks, dt: Self::Ticks);

Such an API should be made available to userspace as well. Or at the very least, the driver should have an additional command to "set alarm from now", in which case the kernel computes now itself, and can internally use the proper set_alarm(now, dt) interface.

[alevy]

@gendx I totally agree. Changing the userspace API would help fix this.

One thing we could try doing in the very immediate future (i.e. pre-2.0) would be to add a system call to the alarm driver for setting an alarm a number of tics in the future in addition to the one setting an absolute tic.

It would push the calculation down to the kernel where there isn't the same kind of delay. It wouldn't be perfect without also fixing the apis in the kernel, but I think it would be a step and wouldn't break anything that currently works.

[alexandruradovici]

I can add the syscall in the kernel, let's see if it works.

The error on my side is that has_expired returns false. I'm not sure I understand how has_expired verifies the expiration, a little background information would help. I am sure I am missing something.