diff --git a/Cargo.lock b/Cargo.lock index 19b984ceb..b149e1625 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5870,6 +5870,7 @@ dependencies = [ "byteorder", "cfg-if", "cortex-m", + "counters", "drv-hash-api", "drv-hf-api", "drv-i2c-api", diff --git a/task/hiffy/Cargo.toml b/task/hiffy/Cargo.toml index 6de62de3d..daf30856f 100644 --- a/task/hiffy/Cargo.toml +++ b/task/hiffy/Cargo.toml @@ -16,6 +16,7 @@ drv-stm32xx-sys-api = { path = "../../drv/stm32xx-sys-api", optional = true } task-net-api = { path = "../../task/net-api", optional = true } hubris-num-tasks = { path = "../../sys/num-tasks", features = ["task-enum"] } ringbuf = { path = "../../lib/ringbuf" } +counters = { path = "../../lib/counters" } static-cell = { path = "../../lib/static-cell" } userlib = { path = "../../sys/userlib" } test-api = { path = "../../test/test-api", optional = true} diff --git a/task/hiffy/src/main.rs b/task/hiffy/src/main.rs index 175c7ee4d..e84f55614 100644 --- a/task/hiffy/src/main.rs +++ b/task/hiffy/src/main.rs @@ -17,6 +17,7 @@ use core::sync::atomic::{AtomicU32, Ordering}; use hif::*; +use ringbuf::{counted_ringbuf, ringbuf_entry}; use static_cell::*; use userlib::*; @@ -185,6 +186,32 @@ pub static HIFFY_VERSION_MINOR: AtomicU32 = AtomicU32::new(HIF_VERSION_MINOR); #[used] pub static HIFFY_VERSION_PATCH: AtomicU32 = AtomicU32::new(HIF_VERSION_PATCH); +#[derive(Copy, Clone, PartialEq, counters::Count)] +enum Trace { + #[count(skip)] + None, + Notified { + bits: u32, + }, + #[cfg(feature = "net")] + NotifiedSocket, + #[cfg(feature = "net")] + RpcReq(#[count(children)] net::RpcOp), + #[cfg(feature = "net")] + RpcReply(#[count(children)] net::RpcReply), + #[cfg(feature = "net")] + WeGetSignal(task_net_api::UdpMetadata), + #[cfg(feature = "net")] + NetRecvErr(task_net_api::RecvError), + NotifiedTimer, + Kicked, + NotKicked, + ExecSuccess, + ExecFailure(Failure), +} + +counted_ringbuf!(Trace, 16, Trace::None); + #[unsafe(export_name = "main")] fn main() -> ! { let mut sleep_ms = 250; @@ -209,86 +236,93 @@ fn main() -> ! { let notif = sys_recv_notification(bits); HIFFY_READY.store(0, Ordering::Relaxed); + ringbuf_entry!(Trace::Notified { + bits: notif.get_raw_bits() + }); #[cfg(feature = "net")] if notif.check_notification_mask(notifications::SOCKET_MASK) { + ringbuf_entry!(Trace::NotifiedSocket); net_state.check_net(); } if notif.has_timer_fired(notifications::TIMER_MASK) { - // Humility writes `1` to `HIFFY_KICK` - if HIFFY_KICK.load(Ordering::Acquire) == 0 { - sleeps += 1; - - // Exponentially backoff our sleep value, but no more than 250ms - if sleeps == 10 { - sleep_ms = core::cmp::min(sleep_ms * 10, 250); - sleeps = 0; - } + ringbuf_entry!(Trace::NotifiedTimer); + } + + // Humility writes `1` to `HIFFY_KICK` + if HIFFY_KICK.load(Ordering::Acquire) == 0 { + ringbuf_entry!(Trace::NotKicked); + sleeps += 1; - continue; + // Exponentially backoff our sleep value, but no more than 250ms + if sleeps == 10 { + sleep_ms = core::cmp::min(sleep_ms * 10, 250); + sleeps = 0; } - // - // Whenever we have been kicked, we adjust our timeout down to 1ms, - // from which we will exponentially backoff - // - HIFFY_KICK.store(0, Ordering::Release); - sleep_ms = 1; - sleeps = 0; - - let check = |offset: usize, op: &Op| -> Result<(), Failure> { - trace_execute(offset, *op); - Ok(()) - }; - let rv = { - // Dummy object to bind references to a non-static lifetime - let lifetime = (); - - // SAFETY: We construct references from our pointers with a limited - // (non-static) lifetime, so they can't escape this block. We are - // in single-threaded code, so no one else can read or write to - // static memory. While the HIF program is running, the debugger is - // only reading from `HIFFY_REQUESTS` and `HIFFY_ERRORS`; it is not - // writing to any locations in memory. See the diagram above for - // Hubris / Humility coordination. - let (text, data, rstack) = unsafe { - ( - bind_lifetime_ref(&lifetime, &raw const HIFFY_TEXT), - bind_lifetime_ref(&lifetime, &raw const HIFFY_DATA), - bind_lifetime_mut(&lifetime, &raw mut HIFFY_RSTACK), - ) - }; - execute::<_, NLABELS>( - text, - HIFFY_FUNCS, - data, - &mut stack, - rstack, - &mut *HIFFY_SCRATCH.borrow_mut(), - check, + continue; + } + ringbuf_entry!(Trace::Kicked); + // + // Whenever we have been kicked, we adjust our timeout down to 1ms, + // from which we will exponentially backoff + // + HIFFY_KICK.store(0, Ordering::Release); + sleep_ms = 1; + sleeps = 0; + + let check = |offset: usize, op: &Op| -> Result<(), Failure> { + trace_execute(offset, *op); + Ok(()) + }; + let rv = { + // Dummy object to bind references to a non-static lifetime + let lifetime = (); + + // SAFETY: We construct references from our pointers with a limited + // (non-static) lifetime, so they can't escape this block. We are + // in single-threaded code, so no one else can read or write to + // static memory. While the HIF program is running, the debugger is + // only reading from `HIFFY_REQUESTS` and `HIFFY_ERRORS`; it is not + // writing to any locations in memory. See the diagram above for + // Hubris / Humility coordination. + let (text, data, rstack) = unsafe { + ( + bind_lifetime_ref(&lifetime, &raw const HIFFY_TEXT), + bind_lifetime_ref(&lifetime, &raw const HIFFY_DATA), + bind_lifetime_mut(&lifetime, &raw mut HIFFY_RSTACK), ) }; - - match rv { - Ok(_) => { - let prev = HIFFY_REQUESTS.load(Ordering::Relaxed); - HIFFY_REQUESTS - .store(prev.wrapping_add(1), Ordering::Release); - trace_success(); - } - Err(failure) => { - // SAFETY: We are in single-threaded code and the debugger will - // not be reading HIFFY_FAILURE until HIFFY_ERRORS is - // incremented below. See the diagram above for Hubris / - // Humility coordination. - unsafe { - HIFFY_FAILURE = Some(failure); - let prev = HIFFY_ERRORS.load(Ordering::Relaxed); - HIFFY_ERRORS - .store(prev.wrapping_add(1), Ordering::Release); - trace_failure(failure); - } + execute::<_, NLABELS>( + text, + HIFFY_FUNCS, + data, + &mut stack, + rstack, + &mut *HIFFY_SCRATCH.borrow_mut(), + check, + ) + }; + + match rv { + Ok(_) => { + let prev = HIFFY_REQUESTS.load(Ordering::Relaxed); + HIFFY_REQUESTS.store(prev.wrapping_add(1), Ordering::Release); + trace_success(); + ringbuf_entry!(Trace::ExecSuccess); + } + Err(failure) => { + // SAFETY: We are in single-threaded code and the debugger will + // not be reading HIFFY_FAILURE until HIFFY_ERRORS is + // incremented below. See the diagram above for Hubris / + // Humility coordination. + unsafe { + HIFFY_FAILURE = Some(failure); + let prev = HIFFY_ERRORS.load(Ordering::Relaxed); + HIFFY_ERRORS.store(prev.wrapping_add(1), Ordering::Release); + trace_failure(failure); + ringbuf_entry!(Trace::ExecFailure(failure)); } } } @@ -328,9 +362,11 @@ unsafe fn bind_lifetime_mut<'a, const N: usize>( #[cfg(feature = "net")] mod net { use super::{ - HIFFY_DATA, HIFFY_KICK, HIFFY_TEXT, bind_lifetime_mut, notifications, + HIFFY_DATA, HIFFY_KICK, HIFFY_TEXT, Trace, bind_lifetime_mut, + notifications, }; use core::sync::atomic::Ordering; + use ringbuf::ringbuf_entry_root; use static_cell::ClaimOnceCell; use task_net_api::{ LargePayloadBehavior, RecvError, SendError, SocketName, UdpMetadata, @@ -360,17 +396,19 @@ mod net { } const CURRENT_VERSION: u16 = 1; - #[derive(Copy, Clone, Debug, FromPrimitive)] + #[derive( + Copy, Clone, Debug, FromPrimitive, PartialEq, Eq, counters::Count, + )] #[repr(u16)] - enum RpcOp { + pub(super) enum RpcOp { WriteHiffyText = 1, WriteHiffyData, HiffyKick, } - #[derive(Copy, Clone, Debug)] + #[derive(Copy, Clone, Debug, PartialEq, Eq, counters::Count)] #[repr(u8)] - enum RpcReply { + pub(super) enum RpcReply { Ok = 0u8, /// The RPC packet was too short to include the complete header TooShort, @@ -419,8 +457,12 @@ mod net { LargePayloadBehavior::Discard, self.rx_data_buf, ) { - Ok(meta) => self.handle_packet(meta), - Err(RecvError::QueueEmpty | RecvError::ServerRestarted) => { + Ok(meta) => { + ringbuf_entry_root!(Trace::WeGetSignal(meta)); + self.handle_packet(meta) + } + Err(err) => { + ringbuf_entry_root!(Trace::NetRecvErr(err)); // Our incoming queue is empty or `net` restarted. Wait for // more packets in dispatch, back in the main loop. } @@ -432,6 +474,7 @@ mod net { // `handle_packet_inner` does not write to it! let tx_data_buf = core::mem::take(&mut self.tx_data_buf); let (r, data) = self.handle_packet_inner(meta); + ringbuf_entry_root!(Trace::RpcReply(r)); tx_data_buf[0] = r as u8; tx_data_buf[1..][..data.len()].copy_from_slice(data); meta.size = (1 + data.len()) as u32; @@ -479,9 +522,15 @@ mod net { return (RpcReply::BadVersion, CURRENT_VERSION.as_bytes()); } + // Decode the requested operation. + let Some(op) = RpcOp::from_u16(header.operation.get()) else { + return (RpcReply::InvalidOperation, &[]); + }; + ringbuf_entry_root!(Trace::RpcReq(op)); + // Perform the actual operation - match RpcOp::from_u16(header.operation.get()) { - Some(RpcOp::WriteHiffyText) => { + match op { + RpcOp::WriteHiffyText => { // Dummy object to bind references to a non-static lifetime let lifetime = (); let offset = header.arg.get() as usize; @@ -504,7 +553,7 @@ mod net { (RpcReply::OutOfRange, &[]) } } - Some(RpcOp::WriteHiffyData) => { + RpcOp::WriteHiffyData => { // Dummy object to bind references to a non-static lifetime let lifetime = (); let offset = header.arg.get() as usize; @@ -527,11 +576,10 @@ mod net { (RpcReply::OutOfRange, &[]) } } - Some(RpcOp::HiffyKick) => { + RpcOp::HiffyKick => { HIFFY_KICK.fetch_add(1, Ordering::SeqCst); (RpcReply::Ok, &[]) } - None => (RpcReply::InvalidOperation, &[]), } } }