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

@@ -44,7 +44,6 @@ impl<R: Read> Parser<R> {
 fn nanx_f64(sign: Sign, payload: &str) -> Result<f64> {
     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<f64> {
 fn nanx_f32(sign: Sign, payload: &str) -> Result<f32> {
     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<f32> {
-    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<f32>
         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<f64> {
-    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<f64>
         result_bits |= 0x8000000000000000;
     }
 
-    println!("f64 bits: {:08x}", result_bits);
     Ok(f64::from_bits(result_bits))
 }
 

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<S: Borrow<str> + Eq + Hash + Display, F>(&self, tag: S, msg: F)
-    where
-        F: Fn() -> String;
+    fn log<F: Fn() -> String>(&self, tag: Tag, msg: F);
 }
 
-#[derive(Debug, Clone)]
-pub struct PrintLogger {
-    tags: HashSet<String>,
+#[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<S: Borrow<str> + Eq + Hash + Display, F>(&self, tag: S, msg: F)
-    where
-        F: Fn() -> String,
-    {
-        if self.tags.contains(tag.borrow()) {
+    fn log<F: Fn() -> String>(&self, tag: Tag, msg: F) {
+        if tag.enabled() {
             let msg = msg();
-            println!("[{}] {}", tag, msg)
+            println!("[{:?}] {}", tag, msg)
         }
     }
 }

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<S: Borrow<str> + Eq + Hash + Display, F>(&self, tag: S, msg: F)
+    fn log<F>(&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<S: Borrow<str> + Eq + Hash + Display, F>(&self, tag: S, msg: F)
-    where
-        F: Fn() -> String,
-    {
+    fn log<F: Fn() -> 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<Value> {
         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<S: Borrow<str> + Eq + Hash + Display, F: Fn() -> String>(&self, tag: S, msg: F) {
+    fn log<F: Fn() -> 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,

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<u8>,
 }
@@ -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<Range<usize>> {
         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());
         }

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::<Result<_>>()?;
         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<GlobalInstance> = 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<u8> = Vec::new();
                 initexpr.emit_expr(&g.init);
                 let val = self.eval_expr(&initexpr)?;
@@ -228,7 +231,7 @@ impl Runtime {
             .collect::<Result<_>>()?;
         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()?;