From a303ea3ff50c68d77679e72f7b67256b992cbd94 Mon Sep 17 00:00:00 2001 From: Vincent Ambo Date: Fri, 2 Sep 2022 23:55:10 +0300 Subject: refactor(tvix/eval): implement much clearer disassembler output With this change the runtime trace contains much more exact information about the context of the computation (entering/exiting calls etc.) This is in large part due to moving the tracer to be a field on the VM itself, which enables consistent ordering of traces across the execution, and tracing an execution with its *input* instead of *output* stack. Change-Id: Ibe525e6e7d869756501e52bef1a441619ce7332c Reviewed-on: https://cl.tvl.fyi/c/depot/+/6419 Reviewed-by: sterni Tested-by: BuildkiteCI --- tvix/eval/src/disassembler.rs | 8 +++-- tvix/eval/src/vm.rs | 68 ++++++++++++++++++++++++++++--------------- 2 files changed, 50 insertions(+), 26 deletions(-) diff --git a/tvix/eval/src/disassembler.rs b/tvix/eval/src/disassembler.rs index e3cc1f16e706..a555f9179102 100644 --- a/tvix/eval/src/disassembler.rs +++ b/tvix/eval/src/disassembler.rs @@ -15,9 +15,7 @@ pub struct Tracer(TabWriter); impl Tracer { pub fn new() -> Self { - let mut tw = TabWriter::new(std::io::stderr()); - write!(&mut tw, "=== runtime trace ===\n").ok(); - Tracer(tw) + Tracer(TabWriter::new(std::io::stderr())) } pub fn trace(&mut self, op: &OpCode, ip: usize, stack: &[Value]) { @@ -29,6 +27,10 @@ impl Tracer { write!(&mut self.0, "]\n").ok(); } + + pub fn literal(&mut self, line: &str) { + let _ = write!(&mut self.0, "{}\n", line); + } } impl Drop for Tracer { diff --git a/tvix/eval/src/vm.rs b/tvix/eval/src/vm.rs index 259fbf7d11f8..b2785c511798 100644 --- a/tvix/eval/src/vm.rs +++ b/tvix/eval/src/vm.rs @@ -11,9 +11,6 @@ use crate::{ value::{Closure, Lambda, NixAttrs, NixList, Thunk, Value}, }; -#[cfg(feature = "disassembler")] -use crate::disassembler::Tracer; - struct CallFrame { lambda: Rc, upvalues: Vec, @@ -35,6 +32,9 @@ pub struct VM { // Stack indices of attribute sets from which variables should be // dynamically resolved (`with`). with_stack: Vec, + + #[cfg(feature = "disassembler")] + pub tracer: crate::disassembler::Tracer, } /// This macro wraps a computation that returns an ErrorKind or a @@ -169,6 +169,13 @@ impl VM { upvalues: Vec, arg_count: usize, ) -> EvalResult { + #[cfg(feature = "disassembler")] + self.tracer.literal(&format!( + "=== entering closure/{} [{}] ===", + arg_count, + self.frames.len() + )); + let frame = CallFrame { lambda, upvalues, @@ -177,15 +184,21 @@ impl VM { }; self.frames.push(frame); - self.run() + let result = self.run(); + + #[cfg(feature = "disassembler")] + self.tracer.literal(&format!( + "=== exiting closure/{} [{}] ===", + arg_count, + self.frames.len() + )); + + result } /// Run the VM's current stack frame to completion and return the /// value. fn run(&mut self) -> EvalResult { - #[cfg(feature = "disassembler")] - let mut tracer = Tracer::new(); - loop { // Break the loop if this call frame has already run to // completion, pop it off, and return the value to the @@ -196,6 +209,10 @@ impl VM { } let op = self.inc_ip(); + + #[cfg(feature = "disassembler")] + self.tracer.trace(&op, self.frame().ip, &self.stack); + match op { OpCode::OpConstant(idx) => { let c = self.chunk().constant(idx).clone(); @@ -426,8 +443,16 @@ impl VM { } Value::Builtin(builtin) => { + #[cfg(feature = "disassembler")] + self.tracer + .literal(&format!("=== entering builtins.{} ===", builtin.name())); + let arg = self.pop(); let result = fallible!(self, builtin.apply(self, arg)); + + #[cfg(feature = "disassembler")] + self.tracer.literal("=== exiting builtin ==="); + self.push(result); } _ => return Err(self.error(ErrorKind::NotCallable)), @@ -501,11 +526,7 @@ impl VM { Value::Thunk(thunk) => thunk .resolve_deferred_upvalues(&self.stack[self.frame().stack_offset..]), - v => { - #[cfg(feature = "disassembler")] - drop(tracer); - panic!("compiler error: invalid finaliser value: {}", v); - } + v => panic!("compiler error: invalid finaliser value: {}", v), } } @@ -519,11 +540,6 @@ impl VM { panic!("VM bug: attempted to execute data-carrying operand") } } - - #[cfg(feature = "disassembler")] - { - tracer.trace(&op, self.frame().ip, &self.stack); - } } } @@ -680,6 +696,17 @@ impl VM { _ => Ok(()), } } + + pub fn new() -> Self { + VM { + frames: vec![], + stack: vec![], + with_stack: vec![], + + #[cfg(feature = "disassembler")] + tracer: crate::disassembler::Tracer::new(), + } + } } // TODO: use Rc::unwrap_or_clone once it is stabilised. @@ -689,12 +716,7 @@ fn unwrap_or_clone_rc(rc: Rc) -> T { } pub fn run_lambda(lambda: Lambda) -> EvalResult { - let mut vm = VM { - frames: vec![], - stack: vec![], - with_stack: vec![], - }; - + let mut vm = VM::new(); let value = vm.call(Rc::new(lambda), vec![], 0)?; vm.force_for_output(&value)?; Ok(value) -- cgit 1.4.1