From e38366c99a4eed9a83083384a5d2d1f0fa186938 Mon Sep 17 00:00:00 2001 From: Sean Cross Date: Wed, 11 Aug 2021 10:59:31 +0800 Subject: [PATCH] log-server: refactor to remove rkyv and custom Strings This removes all custom string formatting from the `log-server`. This should improve performance, because we're not roundtripping between various archive formats. We instead do a single copy and operate directly on that buffer. We also now write bytes directly, as opposed to creating intermediate strings. This fixes a memory issue that was introduced recently. Signed-off-by: Sean Cross --- services/log-server/Cargo.toml | 1 - services/log-server/src/api.rs | 12 +++++--- services/log-server/src/cursor.rs | 43 +++++++++++++++++++++++++++ services/log-server/src/lib.rs | 49 ++++++++++++++++++------------- services/log-server/src/main.rs | 43 ++++++++++++++++++++------- 5 files changed, 112 insertions(+), 36 deletions(-) create mode 100644 services/log-server/src/cursor.rs diff --git a/services/log-server/Cargo.toml b/services/log-server/Cargo.toml index da6f8f655..28145b4a4 100644 --- a/services/log-server/Cargo.toml +++ b/services/log-server/Cargo.toml @@ -9,7 +9,6 @@ version = "0.1.0" log = "0.4" num-derive = {version = "0.3", default-features = false} num-traits = {version = "0.2", default-features = false} -rkyv = {version = "0.4.3", features = ["const_generics"], default-features = false} xous = {path = "../../xous-rs"} xous-ipc = {path = "../../xous-ipc"} diff --git a/services/log-server/src/api.rs b/services/log-server/src/api.rs index 8e8ef9343..af7a7514c 100644 --- a/services/log-server/src/api.rs +++ b/services/log-server/src/api.rs @@ -1,10 +1,14 @@ -#[derive(Debug, rkyv::Archive, rkyv::Serialize, rkyv::Deserialize)] +// #[derive(Debug, rkyv::Archive, rkyv::Serialize, rkyv::Deserialize)] +#[repr(C)] pub struct LogRecord { - pub file: xous_ipc::String<128>, + pub file_length: u32, + pub file: [u8; 128], pub line: Option, - pub module: xous_ipc::String<128>, + pub module_length: u32, + pub module: [u8; 128], pub level: u32, - pub args: xous_ipc::String<2800>, + pub args_length: u32, + pub args: [u8; 3000], } #[derive(Debug, PartialEq, num_derive::FromPrimitive, num_derive::ToPrimitive)] diff --git a/services/log-server/src/cursor.rs b/services/log-server/src/cursor.rs new file mode 100644 index 000000000..0d5f660db --- /dev/null +++ b/services/log-server/src/cursor.rs @@ -0,0 +1,43 @@ +/// no_std replacement for Cursor. + +pub struct BufferWrapper<'a> { + buf: &'a mut [u8], + offset: usize, +} + +impl<'a> BufferWrapper<'a> { + pub fn new(buf: &'a mut [u8]) -> Self { + BufferWrapper { + buf: buf, + offset: 0, + } + } + pub fn len(&self) -> usize { + self.offset + } +} + +impl<'a> core::fmt::Write for BufferWrapper<'a> { + fn write_str(&mut self, s: &str) -> core::fmt::Result { + let bytes = s.as_bytes(); + + // Skip over already-copied data + let remainder = &mut self.buf[self.offset..]; + + // Check if there is space remaining (return error instead of panicking) + if remainder.len() < bytes.len() { + return Err(core::fmt::Error); + } + + // Make the two slices the same length + let remainder = &mut remainder[..bytes.len()]; + + // Copy + remainder.copy_from_slice(bytes); + + // Update offset to avoid overwriting + self.offset += bytes.len(); + + Ok(()) + } +} diff --git a/services/log-server/src/lib.rs b/services/log-server/src/lib.rs index 0fb379b8f..4d86d90b0 100644 --- a/services/log-server/src/lib.rs +++ b/services/log-server/src/lib.rs @@ -2,9 +2,10 @@ use core::fmt::Write; use core::sync::atomic::{AtomicBool, Ordering}; use num_traits::ToPrimitive; -use xous_ipc::{Buffer, String}; +use xous_ipc::Buffer; pub mod api; +mod cursor; #[derive(Debug)] pub enum LogError { @@ -20,12 +21,7 @@ struct XousLogger { locked: AtomicBool, } -// static mut XOUS_LOGGER_BACKING: XousLoggerBacking = XousLoggerBacking { -// conn: 0, -// initialized: false, -// buffer: None, -// }; - +const BUFFER_SIZE: usize = 4096; static mut XOUS_LOGGER_BACKING: Option = None; struct XousLoggerBacking<'a> { @@ -37,8 +33,7 @@ impl<'a> XousLoggerBacking<'a> { pub fn new() -> Result { Ok(XousLoggerBacking { conn: xous::connect(xous::SID::from_bytes(b"xous-log-server ").unwrap())?, - // why 4000? tests non-power of 2 sizes in rkyv APIs. Could make it 4096 as well... - buffer: Buffer::new(4000), + buffer: Buffer::new(BUFFER_SIZE), }) } } @@ -47,25 +42,37 @@ impl Default for XousLoggerBacking<'_> { fn default() -> Self { XousLoggerBacking { conn: xous::connect(xous::SID::from_bytes(b"xous-log-server ").unwrap()).unwrap(), - // why 4000? tests non-power of 2 sizes in rkyv APIs. Could make it 4096 as well... - buffer: Buffer::new(4000), + buffer: Buffer::new(BUFFER_SIZE), } } } impl XousLoggerBacking<'_> { fn log_impl(&mut self, record: &log::Record) { - let mut args = String::<2800>::new(); - write!(args, "{}", record.args()).unwrap(); - let lr = api::LogRecord { - file: String::from_str(record.file().unwrap_or("")), - line: record.line(), - module: String::from_str(record.module_path().unwrap_or("")), - level: record.level() as u32, - args, - }; + { + assert!(core::mem::size_of::() < BUFFER_SIZE); + let log_record = unsafe { &mut *(self.buffer.as_mut_ptr() as *mut api::LogRecord) }; + + log_record.line = record.line(); + log_record.level = record.level() as u32; + + let file = record.file().unwrap_or_default().as_bytes(); + log_record.file_length = file.len() as u32; + for (dest, src) in log_record.file.iter_mut().zip(file) { + *dest = *src; + } + + let module = record.module_path().unwrap_or_default().as_bytes(); + log_record.module_length = module.len() as u32; + for (dest, src) in log_record.module.iter_mut().zip(module) { + *dest = *src; + } + + let mut wrapper = cursor::BufferWrapper::new(&mut log_record.args); + write!(wrapper, "{}", record.args()).unwrap(); + log_record.args_length = wrapper.len() as u32; + } - self.buffer.rewrite(lr).unwrap(); self.buffer .lend(self.conn, crate::api::Opcode::LogRecord.to_u32().unwrap()) .unwrap(); diff --git a/services/log-server/src/main.rs b/services/log-server/src/main.rs index f60e8b675..e5e8678ee 100644 --- a/services/log-server/src/main.rs +++ b/services/log-server/src/main.rs @@ -281,7 +281,7 @@ fn handle_opcode( match opcode { api::Opcode::LogRecord => { let buffer = unsafe { xous_ipc::Buffer::from_memory_message(mem) }; - let lr: LogRecord = buffer.to_original::().unwrap(); + let lr = unsafe { &*(buffer.as_ptr() as *const LogRecord) }; let level = if log::Level::Error as u32 == lr.level { "ERR " } else if log::Level::Warn as u32 == lr.level { @@ -295,16 +295,39 @@ fn handle_opcode( } else { "UNKNOWN" }; - if let Some(line) = lr.line { - writeln!( - output, - "{}:{}: {} ({}:{})", - level, lr.module, lr.args, lr.file, line - ) - .unwrap(); - } else { - writeln!(output, "{}:{}: {} ({})", level, lr.module, lr.args, lr.file).unwrap(); + if lr.file_length as usize >= lr.file.len() { + return; } + if lr.args_length as usize >= lr.args.len() { + return; + } + if lr.module_length as usize > lr.module.len() { + return; + } + + let file_slice = &lr.file[0..lr.file_length as usize]; + + let args_slice = &lr.args[0..lr.args_length as usize]; + + let module_slice = &lr.module[0..lr.module_length as usize]; + + write!(output, "{}:", level).ok(); + for c in module_slice { + output.putc(*c); + } + write!(output, ": ").ok(); + for c in args_slice { + output.putc(*c); + } + + write!(output, " (").ok(); + for c in file_slice { + output.putc(*c); + } + if let Some(line) = lr.line { + write!(output, ":{}", line).ok(); + } + writeln!(output, ")").ok(); } api::Opcode::StandardOutput | api::Opcode::StandardError => { // let mut buffer_start_offset = mem.offset.map(|o| o.get()).unwrap_or(0);