From e61b6458998aa5f1b2a3b0fa3295fbfdf67fe74a Mon Sep 17 00:00:00 2001 From: vms Date: Sun, 13 Sep 2020 22:19:26 +0300 Subject: [PATCH] add instruction tracing --- Cargo.lock | 10 +++++++ Cargo.toml | 1 + src/interpreter/instructions/argument_get.rs | 2 ++ src/interpreter/instructions/byte_arrays.rs | 4 +++ src/interpreter/instructions/call_core.rs | 4 ++- src/interpreter/instructions/dup.rs | 1 + src/interpreter/instructions/numbers.rs | 29 ++++++++++++-------- src/interpreter/instructions/records.rs | 3 ++ src/interpreter/instructions/strings.rs | 4 +++ src/interpreter/instructions/swap2.rs | 1 + 10 files changed, 46 insertions(+), 13 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c0c5cec..aa41388 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -47,6 +47,15 @@ dependencies = [ "static_assertions", ] +[[package]] +name = "log" +version = "0.4.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4fabed175da42fed1fa0746b0ea71f412aa9d35e76e95e59b192c64b9dc2bf8b" +dependencies = [ + "cfg-if", +] + [[package]] name = "memchr" version = "2.3.3" @@ -188,6 +197,7 @@ checksum = "078775d0255232fb988e6fccf26ddc9d1ac274299aaedcedce21c6f72cc533ce" name = "wasmer-interface-types-fl" version = "0.17.3" dependencies = [ + "log", "nom", "safe-transmute", "serde", diff --git a/Cargo.toml b/Cargo.toml index a1b1af2..0b14141 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -17,6 +17,7 @@ wast = "8.0" serde = { version = "1.0", features = ["derive"], optional = true } serde_json = "1.0" safe-transmute = "0.11.0" +log = "0.4.11" [features] default = ["serde"] diff --git a/src/interpreter/instructions/argument_get.rs b/src/interpreter/instructions/argument_get.rs index 3b95405..87cbc52 100644 --- a/src/interpreter/instructions/argument_get.rs +++ b/src/interpreter/instructions/argument_get.rs @@ -15,6 +15,8 @@ executable_instruction!( )); } + log::trace!("arg.get: pushing {:?} on the stack", invocation_inputs[index as usize]); + runtime.stack.push(invocation_inputs[index as usize].clone()); Ok(()) diff --git a/src/interpreter/instructions/byte_arrays.rs b/src/interpreter/instructions/byte_arrays.rs index 4b9fec8..c4f4ede 100644 --- a/src/interpreter/instructions/byte_arrays.rs +++ b/src/interpreter/instructions/byte_arrays.rs @@ -59,6 +59,8 @@ executable_instruction!( .map(Cell::get) .collect(); + log::trace!("bytearray.lift_memory: pushing {:?} on the stack", data); + runtime.stack.push(InterfaceValue::ByteArray(data)); Ok(()) @@ -104,6 +106,8 @@ executable_instruction!( memory_view[byte_array_pointer as usize + nth].set(*byte); } + log::trace!("bytearray.lower_memory: pushing {}, {} on the stack", byte_array_pointer, byte_array_length); + runtime.stack.push(InterfaceValue::I32(byte_array_pointer as i32)); runtime.stack.push(InterfaceValue::I32(byte_array_length)); diff --git a/src/interpreter/instructions/call_core.rs b/src/interpreter/instructions/call_core.rs index 533740c..0f54912 100644 --- a/src/interpreter/instructions/call_core.rs +++ b/src/interpreter/instructions/call_core.rs @@ -31,6 +31,8 @@ executable_instruction!( super::check_function_signature(&**instance, local_or_import, &inputs, instruction)?; + log::trace!("call-core: calling {} with arguments: {:?}", function_index, inputs); + let outputs = local_or_import.call(&inputs).map_err(|_| { InstructionError::new( instruction, @@ -40,7 +42,7 @@ executable_instruction!( ) })?; - + log::trace!("call-core: call to {} succeeded with result {:?}", function_index, outputs); for output in outputs.into_iter() { runtime.stack.push(output) diff --git a/src/interpreter/instructions/dup.rs b/src/interpreter/instructions/dup.rs index f6c6c42..4d455c3 100644 --- a/src/interpreter/instructions/dup.rs +++ b/src/interpreter/instructions/dup.rs @@ -14,6 +14,7 @@ executable_instruction!( })?; let value = value.clone(); + log::trace!("dup: duplication {:?} value on the stack", value); runtime.stack.push(value); Ok(()) diff --git a/src/interpreter/instructions/numbers.rs b/src/interpreter/instructions/numbers.rs index e2d4d79..53e4ad3 100644 --- a/src/interpreter/instructions/numbers.rs +++ b/src/interpreter/instructions/numbers.rs @@ -15,19 +15,24 @@ macro_rules! lowering_lifting { Some(InterfaceValue::$from_variant(value)) => { runtime .stack - .push(InterfaceValue::$to_variant(value.try_into().map_err( - |_| { - InstructionError::new( - instruction, - InstructionErrorKind::LoweringLifting { - from: InterfaceType::$from_variant, - to: InterfaceType::$to_variant - }, - ) - }, - )?)) - } + .push({ + let converted_value = InterfaceValue::$to_variant(value.try_into().map_err( + |_| { + InstructionError::new( + instruction, + InstructionErrorKind::LoweringLifting { + from: InterfaceType::$from_variant, + to: InterfaceType::$to_variant + }, + ) + }, + )?); + log::trace!("{}: converting {:?} to {:?}", $instruction_name, value, converted_value); + + converted_value + }) + } Some(wrong_value) => { return Err(InstructionError::new( instruction, diff --git a/src/interpreter/instructions/records.rs b/src/interpreter/instructions/records.rs index 45379a9..af25972 100644 --- a/src/interpreter/instructions/records.rs +++ b/src/interpreter/instructions/records.rs @@ -288,6 +288,8 @@ where })?; let record = record_lift_memory_(&**instance, record_type, offset, instruction)?; + + log::trace!("record.lift_memory: pushing {:?} on the stack", record); runtime.stack.push(record); Ok(()) @@ -349,6 +351,7 @@ where InterfaceValue::Record(values) => { let record_ptr = record_lower_memory_(instance, instruction, values)?; + log::trace!("record.lower_memory: pushing {:?} on the stack", record_ptr); result.push(record_ptr as _); } } diff --git a/src/interpreter/instructions/strings.rs b/src/interpreter/instructions/strings.rs index 1b36cb9..93876bd 100644 --- a/src/interpreter/instructions/strings.rs +++ b/src/interpreter/instructions/strings.rs @@ -62,6 +62,7 @@ executable_instruction!( let string = String::from_utf8(data) .map_err(|error| InstructionError::new(instruction, InstructionErrorKind::String(error)))?; + log::trace!("string.lift_memory: pushing {:?} on the stack", string); runtime.stack.push(InterfaceValue::String(string)); Ok(()) @@ -108,6 +109,7 @@ executable_instruction!( memory_view[string_pointer as usize + nth].set(*byte); } + log::trace!("string.lower_memory: pushing {}, {} on the stack", string_pointer, string_length); runtime.stack.push(InterfaceValue::I32(string_pointer as i32)); runtime.stack.push(InterfaceValue::I32(string_length)); @@ -122,6 +124,8 @@ executable_instruction!( match runtime.stack.pop1() { Some(InterfaceValue::String(string)) => { let length = string.len() as i32; + + log::trace!("string.size: pushing {} on the stack", length); runtime.stack.push(InterfaceValue::I32(length)); Ok(()) diff --git a/src/interpreter/instructions/swap2.rs b/src/interpreter/instructions/swap2.rs index 5e465b4..6a487c5 100644 --- a/src/interpreter/instructions/swap2.rs +++ b/src/interpreter/instructions/swap2.rs @@ -13,6 +13,7 @@ executable_instruction!( ) })?; + log::trace!("swap2: swapping {:?}, {:?} values on the stack", values[0], values[1]); runtime.stack.push(values.remove(1)); runtime.stack.push(values.remove(0));