From 31f4c0b5423a46091ee299df0c0caca92636eea1 Mon Sep 17 00:00:00 2001 From: Jason LeBrun Date: Fri, 15 Dec 2023 13:41:34 -0800 Subject: [PATCH] Improve logging system * Hash lookups are way to slow to use for logging. Switch to tags with a boolean enable bit. This is a better log tag management approach, anyway, since we can now see all tags in one place. * Remove a number of println! in favor of logs. Test runtime is significantly faster now. --- src/format/text/parse/num.rs | 18 +--------- src/logger/mod.rs | 50 ++++++++++++++++------------ src/runtime/exec.rs | 27 +++++++-------- src/runtime/instance/mem_instance.rs | 17 ++++++++-- src/runtime/instantiate.rs | 34 ++++++++++--------- src/runtime/mod.rs | 10 +++--- src/runtime/stack.rs | 32 ++++++++++-------- src/spec/runner.rs | 17 +++++----- tests/meminstr32/mod.rs | 10 +++--- tests/meminstr64/mod.rs | 22 ++++++------ tests/spec_runner/mod.rs | 2 +- 11 files changed, 123 insertions(+), 116 deletions(-) diff --git a/src/format/text/parse/num.rs b/src/format/text/parse/num.rs index d84eca3b..f8deaaf5 100644 --- a/src/format/text/parse/num.rs +++ b/src/format/text/parse/num.rs @@ -44,7 +44,6 @@ impl Parser { fn nanx_f64(sign: Sign, payload: &str) -> Result { let payload = payload.replace('_', ""); let payload_num = u64::from_str_radix(&payload, 16)?; - println!("PAYLOAD NUM {:013x}", payload_num); let base: u64 = match sign { Sign::Negative => 0xFFF0000000000000, _ => 0x7FF0000000000000, @@ -55,7 +54,6 @@ fn nanx_f64(sign: Sign, payload: &str) -> Result { fn nanx_f32(sign: Sign, payload: &str) -> Result { let payload = payload.replace('_', ""); let payload_num = u32::from_str_radix(&payload, 16)?; - println!("PAYLOAD NUM {:06x}", payload_num); let base: u32 = match sign { Sign::Negative => 0xFF800000, _ => 0x7F800000, @@ -81,7 +79,6 @@ macro_rules! parse_float { match base { Base::Dec => { let to_parse = format!("{}{}.{}e{}", sign.char(), whole, frac, exp); - println!("PARSE DECIMAL FLOAT {}", to_parse); Ok(to_parse.parse::<$ty>()?) } Base::Hex => $hex(*sign, whole, frac, exp), @@ -92,10 +89,7 @@ macro_rules! parse_float { let to_parse = format!("{}{}", sign.char(), digits); Ok(to_parse.parse::<$ty>()?) } - Base::Hex => { - println!("TRY INT AS HEX {}", digits); - $hex(*sign, digits, "", "0") - } + Base::Hex => $hex(*sign, digits, "", "0"), }, } } @@ -216,10 +210,6 @@ impl FloatBuilder { let roundpart = self.bits & roundmask; let mantissa_lsb = self.bits & even << 1; let round = roundpart > even || roundpart == even && mantissa_lsb != 0; - println!(" SUBJECT: {:016x}", self.bits); - println!("ROUNDMASK: {:016x}", roundmask); - println!("ROUNDPART: {:016x}", roundpart); - println!(" EVEN: {:016x}", even); self.bits >>= 64 - size; @@ -267,8 +257,6 @@ impl FloatBuilder { } fn parse_hex_f32(sign: Sign, whole: &str, frac: &str, exp: &str) -> Result { - println!("\n\nPARSE HEX F32 {:?} {} {} {}", sign, whole, frac, exp); - let builder = FloatBuilder::new(whole, frac, exp)?; let mut result_bits = builder.build(f32::MANTISSA_DIGITS, 127)? as u32; @@ -277,13 +265,10 @@ fn parse_hex_f32(sign: Sign, whole: &str, frac: &str, exp: &str) -> Result result_bits |= 0x80000000; } - println!("f32 bits: {:08x}", result_bits); Ok(f32::from_bits(result_bits)) } fn parse_hex_f64(sign: Sign, whole: &str, frac: &str, exp: &str) -> Result { - println!("PARSE HEX F64 {:?} {} {} {}", sign, whole, frac, exp); - let builder = FloatBuilder::new(whole, frac, exp)?; let mut result_bits = builder.build(f64::MANTISSA_DIGITS, 1023)?; @@ -292,7 +277,6 @@ fn parse_hex_f64(sign: Sign, whole: &str, frac: &str, exp: &str) -> Result result_bits |= 0x8000000000000000; } - println!("f64 bits: {:08x}", result_bits); Ok(f64::from_bits(result_bits)) } diff --git a/src/logger/mod.rs b/src/logger/mod.rs index 80c2805a..4ca48835 100644 --- a/src/logger/mod.rs +++ b/src/logger/mod.rs @@ -1,35 +1,41 @@ -use std::fmt::Display; -use std::{borrow::Borrow, collections::HashSet, hash::Hash}; - pub trait Logger { - fn log + Eq + Hash + Display, F>(&self, tag: S, msg: F) - where - F: Fn() -> String; + fn log String>(&self, tag: Tag, msg: F); } -#[derive(Debug, Clone)] -pub struct PrintLogger { - tags: HashSet, +#[derive(Debug, Clone, Default)] +pub struct PrintLogger; + +#[derive(Debug)] +pub enum Tag { + Activate, + Enter, + Flow, + Load, + Local, + Mem, + Op, + Host, + Spec, + + Stack, + LabelStack, + ValStack, + DumpStack, + DumpLabelStack, + DumpValStack, } -impl Default for PrintLogger { - fn default() -> Self { - let mut tags = HashSet::default(); - tags.insert("SPEC".to_owned()); - tags.insert("LOAD".to_owned()); - tags.insert("HOST".to_owned()); - Self { tags } +impl Tag { + fn enabled(&self) -> bool { + matches!(self, Tag::Load | Tag::Spec | Tag::Host) } } impl Logger for PrintLogger { - fn log + Eq + Hash + Display, F>(&self, tag: S, msg: F) - where - F: Fn() -> String, - { - if self.tags.contains(tag.borrow()) { + fn log String>(&self, tag: Tag, msg: F) { + if tag.enabled() { let msg = msg(); - println!("[{}] {}", tag, msg) + println!("[{:?}] {}", tag, msg) } } } diff --git a/src/runtime/exec.rs b/src/runtime/exec.rs index c1d357fd..63623fcd 100644 --- a/src/runtime/exec.rs +++ b/src/runtime/exec.rs @@ -10,8 +10,8 @@ use super::{ use crate::runtime::instance::MemInstance; use crate::runtime::stack::Label; use crate::{impl_bug, instructions::exec_method}; -use crate::{logger::Logger, types::RefType}; -use std::{borrow::Borrow, convert::TryFrom, convert::TryInto, fmt::Display, hash::Hash}; +use crate::{logger::Logger, logger::Tag, types::RefType}; +use std::{convert::TryFrom, convert::TryInto}; pub struct ExecutionContext<'l> { runtime: &'l mut Runtime, @@ -20,7 +20,7 @@ pub struct ExecutionContext<'l> { } pub trait ExecutionContextActions { - fn log + Eq + Hash + Display, F>(&self, tag: S, msg: F) + fn log(&self, tag: Tag, msg: F) where F: Fn() -> String; fn next_byte(&mut self) -> u8; @@ -155,10 +155,7 @@ pub trait ExecutionContextActions { } impl<'l> ExecutionContextActions for ExecutionContext<'l> { - fn log + Eq + Hash + Display, F>(&self, tag: S, msg: F) - where - F: Fn() -> String, - { + fn log String>(&self, tag: Tag, msg: F) { self.runtime.logger.log(tag, msg); } @@ -199,12 +196,12 @@ impl<'l> ExecutionContextActions for ExecutionContext<'l> { fn get_local(&mut self, idx: u32) -> Result { let val = self.runtime.stack.get_local(idx); - self.log("LOCAL", || format!("GET {} {:?}", idx, val)); + self.log(Tag::Local, || format!("GET {} {:?}", idx, val)); val } fn set_local(&mut self, idx: u32, val: Value) -> Result<()> { - self.log("LOCAL", || format!("SET {} {:?}", idx, val)); + self.log(Tag::Local, || format!("SET {} {:?}", idx, val)); self.runtime.stack.set_local(idx, val) } @@ -245,7 +242,7 @@ impl<'l> ExecutionContextActions for ExecutionContext<'l> { fn mem(&mut self, idx: u32) -> Result<&mut MemInstance> { let memaddr = self.runtime.stack.get_mem_addr(idx)?; - self.log("MEM", || format!("USING MEM {:?}", memaddr)); + self.log(Tag::Mem, || format!("USING MEM {:?}", memaddr)); self.runtime.store.mem(memaddr) } @@ -387,7 +384,7 @@ impl<'l> ExecutionContextActions for ExecutionContext<'l> { fn continuation(&mut self, cnt: u32) -> Result<()> { self.pc = cnt as usize; - self.log("FLOW", || format!("CONTINUE AT {:x}", cnt)); + self.log(Tag::Flow, || format!("CONTINUE AT {:x}", cnt)); if self.pc >= self.body.len() { panic!( "invalid continuation {} for body size {}", @@ -483,10 +480,10 @@ impl<'l> ExecutionContext<'l> { pub fn run(&mut self) -> Result<()> { while self.pc < self.body.len() { let op = self.body[self.pc]; - self.log("OP", || format!("BEGIN 0x{:x}", op)); + self.log(Tag::Op, || format!("BEGIN 0x{:x}", op)); self.pc += 1; exec_method(op, self)?; - self.log("OP", || format!("FINISHED 0x{:x}", op)); + self.log(Tag::Op, || format!("FINISHED 0x{:x}", op)); } Ok(()) } @@ -508,12 +505,12 @@ impl<'a> std::fmt::Display for Body<'a> { /// Implementation of instruction implementation for this runtime. impl Runtime { - fn log + Eq + Hash + Display, F: Fn() -> String>(&self, tag: S, msg: F) { + fn log String>(&self, tag: Tag, msg: F) { self.logger.log(tag, msg); } pub fn enter(&mut self, body: &[u8]) -> Result<()> { - self.log("ENTER", || format!("ENTER EXPR {}", Body(body))); + self.log(Tag::Enter, || format!("ENTER EXPR {}", Body(body))); let mut ic = ExecutionContext { runtime: self, body, diff --git a/src/runtime/instance/mem_instance.rs b/src/runtime/instance/mem_instance.rs index 3a7a054b..5e4594cc 100644 --- a/src/runtime/instance/mem_instance.rs +++ b/src/runtime/instance/mem_instance.rs @@ -1,5 +1,6 @@ use std::ops::Range; +use crate::logger::{Logger, PrintLogger, Tag}; use crate::runtime::error::Result; use crate::{runtime::error::TrapKind, syntax::MemoryField, types::MemType}; @@ -18,6 +19,7 @@ use crate::{runtime::error::TrapKind, syntax::MemoryField, types::MemType}; /// [Spec]: https://webassembly.github.io/spec/core/exec/runtime.html#memory-instances #[derive(Default, Debug)] pub struct MemInstance { + logger: PrintLogger, pub memtype: MemType, pub data: Vec, } @@ -33,13 +35,21 @@ impl MemInstance { /// [Spec]: https://webassembly.github.io/spec/core/exec/runtime.html#memory-instances pub fn new(memtype: MemType) -> MemInstance { let data = vec![0u8; memtype.limits.lower as usize * PAGE_SIZE]; - MemInstance { memtype, data } + MemInstance { + logger: PrintLogger, + memtype, + data, + } } pub fn new_ast(memfield: MemoryField) -> MemInstance { let memtype = memfield.memtype; let data = vec![0u8; memtype.limits.lower as usize * PAGE_SIZE]; - MemInstance { memtype, data } + MemInstance { + logger: PrintLogger, + memtype, + data, + } } pub fn size(&self) -> usize { @@ -67,7 +77,8 @@ impl MemInstance { fn offset(&self, o: usize, b: usize, n: usize) -> Result> { let i = o as u64 + b as u64; - println!("READ {} IN {}", i, self.data.len()); + self.logger + .log(Tag::Mem, || format!("READ {} IN {}", i, self.data.len())); if (i + n as u64) > self.data.len() as u64 { return Err(TrapKind::OutOfBoundsMemoryAccess.into()); } diff --git a/src/runtime/instantiate.rs b/src/runtime/instantiate.rs index 323c4fec..99f9d166 100644 --- a/src/runtime/instantiate.rs +++ b/src/runtime/instantiate.rs @@ -7,7 +7,7 @@ use super::{ Runtime, }; use crate::{ - logger::Logger, + logger::{Logger, Tag}, runtime::{ compile::compile_export, instance::{DataInstance, ElemInstance, GlobalInstance, MemInstance, TableInstance}, @@ -142,7 +142,7 @@ impl Runtime { let range = self.store.alloc_funcs(func_insts.iter().cloned()); modinst_builder.funcs.extend(range); - self.logger.log("LOAD", || { + self.logger.log(Tag::Load, || { format!("LOADED FUNCTIONS {:?}", modinst_builder.funcs) }); @@ -153,15 +153,16 @@ impl Runtime { .collect(); let range = self.store.alloc_tables(table_insts.into_iter()); modinst_builder.tables.extend(range); - self.logger.log("LOAD", || { + self.logger.log(Tag::Load, || { format!("LOADED TABLES {:?}", modinst_builder.tables) }); let mem_insts = module.memories.into_iter().map(MemInstance::new_ast); let range = self.store.alloc_mems(mem_insts); modinst_builder.mems.extend(range); - self.logger - .log("LOAD", || format!("LOADED MEMS {:?}", modinst_builder.mems)); + self.logger.log(Tag::Load, || { + format!("LOADED MEMS {:?}", modinst_builder.mems) + }); // (Instantiation 5-10.) Generate global and elem init values // (Instantiation 5.) Create the module instance for global initialization @@ -195,7 +196,7 @@ impl Runtime { .collect::>()?; let range = self.store.alloc_elems(elem_insts.into_iter()); modinst_builder.elems.extend(range); - self.logger.log("LOAD", || { + self.logger.log(Tag::Load, || { format!("LOADED ELEMS {:?}", modinst_builder.elems) }); @@ -207,16 +208,18 @@ impl Runtime { let range = self.store.alloc_data(data_insts.into_iter()); modinst_builder.data.extend(range); - self.logger - .log("LOAD", || format!("LOADED DATA {:?}", modinst_builder.data)); + self.logger.log(Tag::Load, || { + format!("LOADED DATA {:?}", modinst_builder.data) + }); // (Instantiation 8.) Get global init vals and allocate globals. let global_insts: Vec = module .globals .iter() .map(|g| { - self.logger - .log("LOAD", || format!("COMPILE GLOBAL INIT EXPR {:x?}", g.init)); + self.logger.log(Tag::Load, || { + format!("COMPILE GLOBAL INIT EXPR {:x?}", g.init) + }); let mut initexpr: Vec = Vec::new(); initexpr.emit_expr(&g.init); let val = self.eval_expr(&initexpr)?; @@ -228,7 +231,7 @@ impl Runtime { .collect::>()?; let range = self.store.alloc_globals(global_insts.into_iter()); modinst_builder.globals.extend(range); - self.logger.log("LOAD", || { + self.logger.log(Tag::Load, || { format!("LOADED GLOBALS {:?}", modinst_builder.globals) }); @@ -248,7 +251,7 @@ impl Runtime { for (i, elem) in module.elems.iter().enumerate() { if let ModeEntry::Active(tp) = &elem.mode { self.logger - .log("LOAD", || format!("INIT ELEMS!i {:?}", elem)); + .log(Tag::Load, || format!("INIT ELEMS!i {:?}", elem)); self.init_table(tp, &elem.elemlist, i as u32)? } } @@ -257,7 +260,7 @@ impl Runtime { for (i, initrec) in data_inits.iter().enumerate() { if let Some(init) = &initrec.0 { self.logger - .log("LOAD", || format!("INIT MEMORY !i {:?}", init)); + .log(Tag::Load, || format!("INIT MEMORY !i {:?}", init)); self.init_mem(init, initrec.1 as u32, i as u32)? } } @@ -273,8 +276,9 @@ impl Runtime { .map(|e| compile_export(e, &rcinst)) .collect(); - self.logger - .log("LOAD", || format!("EXPORTS {:?}", modinst_builder.exports)); + self.logger.log(Tag::Load, || { + format!("EXPORTS {:?}", modinst_builder.exports) + }); self.stack.pop_activation()?; diff --git a/src/runtime/mod.rs b/src/runtime/mod.rs index 0782f025..b3ee2f45 100644 --- a/src/runtime/mod.rs +++ b/src/runtime/mod.rs @@ -9,7 +9,7 @@ pub mod values; use crate::{ impl_bug, - logger::{Logger, PrintLogger}, + logger::{Logger, PrintLogger, Tag}, runtime::error::RuntimeErrorKind, }; use std::{collections::HashMap, rc::Rc}; @@ -82,7 +82,7 @@ impl Runtime { // Due to validation, this should be equal to the frame above. self.stack.pop_activation()?; - self.logger.log("ACTIVATION", || { + self.logger.log(Tag::Activate, || { format!( "REMOVE FRAME {} {} {}", funcinst.locals.len(), @@ -110,7 +110,7 @@ impl Runtime { }?; self.logger - .log("HOST", || format!("calling {} at {}", name, funcaddr)); + .log(Tag::Host, || format!("calling {} at {}", name, funcaddr)); // 1. Assert S.funcaddr exists // 2. Let funcinst = S.funcs[funcaddr] let funcinst = self.store.func(funcaddr)?; @@ -137,7 +137,7 @@ impl Runtime { let result = self.stack.pop_value()?; self.logger - .log("HOST", || format!("POPPED HOST RESULT {:?}", result)); + .log(Tag::Host, || format!("POPPED HOST RESULT {:?}", result)); results.push(result); } @@ -170,7 +170,7 @@ impl Runtime { }?; self.logger - .log("HOST", || format!("calling {} at {}", name, globaladdr)); + .log(Tag::Host, || format!("calling {} at {}", name, globaladdr)); // 1. Assert S.funcaddr exists // 2. Let funcinst = S.funcs[funcaddr] let globalinst = self.store.global(globaladdr)?; diff --git a/src/runtime/stack.rs b/src/runtime/stack.rs index f8c568a7..1899b40e 100644 --- a/src/runtime/stack.rs +++ b/src/runtime/stack.rs @@ -1,7 +1,7 @@ use super::error::Result; use super::ModuleInstance; use super::{instance::FunctionInstance, store::addr, values::Value}; -use crate::logger::{Logger, PrintLogger}; +use crate::logger::{Logger, PrintLogger, Tag}; use crate::{impl_bug, types::FunctionType}; use std::rc::Rc; @@ -63,9 +63,10 @@ struct ActivationFrame { impl Stack { pub fn push_value(&mut self, entry: Value) { self.value_stack.push(entry); - self.logger.log("VALSTACK", || format!("PUSH {:?}", entry)); self.logger - .log("DUMPVALSTACK", || format!("{:?}", self.value_stack)); + .log(Tag::ValStack, || format!("PUSH {:?}", entry)); + self.logger + .log(Tag::DumpValStack, || format!("{:?}", self.value_stack)); } fn label_stack(&self) -> Result<&Vec