single-byte console writes never complete #1736
Comments
|
Btw, the frequency seem off on your platform.
There are roughly 6 seconds between loop iterations, whereas the waiting time should be of 500ms. Or is that a side-effect of Tockilator's tracing, which slows down everything? I don't see any 10KHz frequency in https://github.com/tock/tock/blob/master/kernel/src/hil/time.rs. |
|
I believe the "bug" is in the lowrisc uart driver, specifically this block: tock/chips/lowrisc/src/uart.rs Lines 211 to 218 in b02fe52 That client callback is in the We also have the |
It's a side effect of running Ibex in Verilator, which (as you can imagine!) does indeed distort time. To run under Verialtor, you need to set |
Well, considering that one of the most basic libtock-rs examples doesn't currently run on OpenTitan/Earl Grey, I would say that it's just a bug -- air quotes definitely not required! I will leave to others whether the bug is in the UART driver or in the virtual UART, but if the bug is believed to be in the UART vs. the virtual UART, I would add that:
Lines 224 to 242 in b02fe52
|
|
To summarize:
Suggestions:
|
Speaking from experience here, been tearing my hair out on one of these bugs for weeks: Many developers will run into these issues way before even trying to contribute. Requiring a callback from a different call stack (using deferred calls or interrupts) is something very common within Tock, which is as @alevy beautifully outlined not something obvious and even worse, not particularly good or visibly documented. This is a core concept every Tock kernel developer should know about and requires careful and beginner friendly explanation somewhere near the beginning of a getting started guide. I don't know the best place to put it but given a pointer can certainly try to draft a documentation. |
|
@lschuermann a draft document is the best (and only) place to start for any document! And I agree it really needs to be very visible. |
|
For better abstractions, @bradjc had an interesting idea: use a capability for doing "upcalls" that would be required by traits that define upcalls and would be passed up somewhere very low in the interrupt handling chain. To flesh this out a tiny bit, you might imagine something like: unsafe trait UpCallCap {}
trait TransmitClient {
/// Just the existing client trait except it takes an `upcall` capability
fn transmitted_buffer(&self, upcall: &mut UpCallCap, tx_buffer: &'static mut [u8], tx_len: usize, rval: ReturnCode);
...
}
trait Transmit {
/// This is unchanged
fn transmit_buffer(&self,
tx_buffer: &'static mut [u8],
tx_len: usize,
) -> (ReturnCode, Option<&'static mut [u8]>);
...
}
impl OpenTitanUart {
pub fn handle_interrupt(&self, upcall: &mut UpCallCap) {
// do stuff
self.client.map(|client| client.transmitted_buffer(upcall, buffer, ...));
// etc
}
}
impl Transmit for OpenTitanUart {
// Note that this doesn't have access to an `UpCallCap` capability
fn transmit_buffer(&self,
tx_buffer: &'static mut [u8],
tx_len: usize,
) -> (ReturnCode, Option<&'static mut [u8]>) {
if tx_len == 1 {
self.registers.tx.write(tx_buffer[0]);
// Oh how I wish I could just call `transmitted_buffer` on the client, but I can't because I don't have the capability to do so, so I guess I'll rewrite my logic to work through the interrupt call path!
}
}
...
} |
Currently, the timer example from libtock-rs hangs, after emitting a single
[:I looked at a trace under Tockilator (and because it's instructive, I have also pushed everything needed to reproduce this to the example/libtock-rs/timer subdirectory).
For starters, here is the output showing just system calls:
So we're doing a one-byte write to the console -- and if the subscribe callback is called, it's certainly not making any other system calls. For starters, it's helpful to confirm this by specifying the Tock application
timer.elfbinary to Tockilator:This shows us that we're not getting back to user-level. To show what's going on, let's look at Tock itself from cycle 353912 on:
The actual write of the one character we see ('[', 0x5b) occurs at cycle 354067. The
callthat begins this output is GOFF 0x13437. We can look at the Gimlidwarfdump -Goutput of theopentitan.elfbinary to better understand this:0x10f is 270, and corresponds to this code:
tock/capsules/src/virtual_uart.rs
Lines 270 to 274 in b02fe52
Which is to say, this code:
tock/capsules/src/virtual_uart.rs
Lines 195 to 225 in b02fe52
In the output above, we can see that the call to
transmit_bufferon line 202 is at cycle 353991. This kicks off the actual write (again, at cycle 354067). Because it's a one-byte write, this brings us into this code at cycle 354099:tock/chips/lowrisc/src/uart.rs
Lines 211 to 217 in b02fe52
This takes into this code at cycle 354121:
tock/capsules/src/virtual_uart.rs
Lines 67 to 75 in b02fe52
From the trace, it's clear that we call immediately back into
do_next_op-- we do not in fact call thetransmitted_buffercallback that will allow our application to execute on its subscription. And from the code and trace, the reason is also clear:self.inflighthasn't (yet) been set, so the callback won't be called. This is the problem: indo_next_op,self.inflightis set after the call to transmit over the UART, when it should actually be set before the call to assure thattransmitted_bufferproperly propagates it.In prototyping a fix for this, it became clear that the code suffers from a second problem, that will have similar symptoms: in addition to setting
self.inflightin the wrong place,do_next_opalso sets it unconditionally with respect totx_buffer-- meaning that it in addition to not settingself.inflightwhen there is in fact data in-flight, it can also setself.inflightwhen there is nothing in-flight.Here is a fix that fixes both problems:
With this fix, the libtock-rs timer example runs correctly:
The text was updated successfully, but these errors were encountered: