Tweak logging

- The logging in step.rs becomes debug! to make it stand out a bit more
- Dump value of operands (in `eval_operands`)
- Try to log a bit less verbose

Author: RalfJung

src/librustc_mir/interpret/operand.rs

@@ -395,21 +395,23 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
     }
 
     /// Evaluate the operand, returning a place where you can then find the data.
-    pub fn eval_operand(&mut self, op: &mir::Operand<'tcx>) -> EvalResult<'tcx, OpTy<'tcx>> {
+    pub fn eval_operand(&mut self, mir_op: &mir::Operand<'tcx>) -> EvalResult<'tcx, OpTy<'tcx>> {
         use rustc::mir::Operand::*;
-        match *op {
+        let op = match *mir_op {
             // FIXME: do some more logic on `move` to invalidate the old location
             Copy(ref place) |
             Move(ref place) =>
-                self.eval_place_to_op(place),
+                self.eval_place_to_op(place)?,
 
             Constant(ref constant) => {
-                let ty = self.monomorphize(op.ty(self.mir(), *self.tcx), self.substs());
+                let ty = self.monomorphize(mir_op.ty(self.mir(), *self.tcx), self.substs());
                 let layout = self.layout_of(ty)?;
                 let op = self.const_value_to_op(constant.literal.val)?;
-                Ok(OpTy { op, layout })
+                OpTy { op, layout }
             }
-        }
+        };
+        trace!("{:?}: {:?}", mir_op, *op);
+        Ok(op)
     }
 
     /// Evaluate a bunch of operands at once

src/librustc_mir/interpret/place.rs

@@ -516,6 +516,7 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
         src_val: Value,
         dest : PlaceTy<'tcx>,
     ) -> EvalResult<'tcx> {
+        trace!("write_value: {:?} <- {:?}", *dest, src_val);
         // See if we can avoid an allocation. This is the counterpart to `try_read_value`,
         // but not factored as a separate function.
         match dest.place {
@@ -543,7 +544,6 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
         value: Value,
         dest: MPlaceTy<'tcx>,
     ) -> EvalResult<'tcx> {
-        trace!("write_value_to_ptr: {:#?}, {:#?}", value, dest.layout);
         assert_eq!(dest.extra, PlaceExtra::None);
         // Note that it is really important that the type here is the right one, and matches the type things are read at.
         // In case `src_val` is a `ScalarPair`, we don't do any magic here to handle padding properly, which is only
@@ -584,8 +584,8 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
         src: OpTy<'tcx>,
         dest: PlaceTy<'tcx>,
     ) -> EvalResult<'tcx> {
-        trace!("Copying {:?} to {:?}", src, dest);
-        assert_eq!(src.layout.size, dest.layout.size, "Size mismatch when copying!");
+        assert_eq!(src.layout.size, dest.layout.size,
+            "Size mismatch when copying!\nsrc: {:#?}\ndest: {:#?}", src, dest);
 
         // Let us see if the layout is simple so we take a shortcut, avoid force_allocation.
         let (src_ptr, src_align) = match self.try_read_value(src)? {
@@ -595,6 +595,7 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
             Err(mplace) => mplace.to_scalar_ptr_align(),
         };
         // Slow path, this does not fit into an immediate. Just memcpy.
+        trace!("copy_op: {:?} <- {:?}", *dest, *src);
         let (dest_ptr, dest_align) = self.force_allocation(dest)?.to_scalar_ptr_align();
         self.memory.copy(
             src_ptr, src_align,

src/librustc_mir/interpret/step.rs

@@ -67,7 +67,7 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
     }
 
     fn statement(&mut self, stmt: &mir::Statement<'tcx>) -> EvalResult<'tcx> {
-        trace!("{:?}", stmt);
+        debug!("{:?}", stmt);
 
         use rustc::mir::StatementKind::*;
 
@@ -281,12 +281,12 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
     }
 
     fn terminator(&mut self, terminator: &mir::Terminator<'tcx>) -> EvalResult<'tcx> {
-        trace!("{:?}", terminator.kind);
+        debug!("{:?}", terminator.kind);
         self.tcx.span = terminator.source_info.span;
         self.memory.tcx.span = terminator.source_info.span;
         self.eval_terminator(terminator)?;
         if !self.stack.is_empty() {
-            trace!("// {:?}", self.frame().block);
+            debug!("// {:?}", self.frame().block);
         }
         Ok(())
     }

src/librustc_mir/interpret/terminator/drop.rs

@@ -13,7 +13,6 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
         span: Span,
         target: BasicBlock,
     ) -> EvalResult<'tcx> {
-        trace!("drop_place: {:#?}", place);
         // We take the address of the object.  This may well be unaligned, which is fine for us here.
         // However, unaligned accesses will probably make the actual drop implementation fail -- a problem shared
         // by rustc.
@@ -29,7 +28,7 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
         span: Span,
         target: BasicBlock,
     ) -> EvalResult<'tcx> {
-        trace!("drop: {:#?}, {:?}, {:?}", arg, ty.sty, instance.def);
+        trace!("drop: {:?},\n  {:?}, {:?}", arg, ty.sty, instance.def);
 
         let instance = match ty.sty {
             ty::TyDynamic(..) => {

src/librustc_mir/interpret/terminator/mod.rs

@@ -38,7 +38,7 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
             } => {
                 let discr_val = self.eval_operand(discr)?;
                 let discr = self.read_value(discr_val)?;
-                trace!("SwitchInt({:#?})", *discr);
+                trace!("SwitchInt({:?})", *discr);
 
                 // Branch to the `otherwise` case by default, if no match is found.
                 let mut target_block = targets[targets.len() - 1];
@@ -286,10 +286,10 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
                     // and need to pack arguments
                     Abi::Rust => {
                         trace!(
-                            "arg_locals: {:#?}",
-                            self.frame().mir.args_iter().collect::<Vec<_>>()
+                            "args: {:#?}",
+                            self.frame().mir.args_iter().zip(args.iter())
+                                .map(|(local, arg)| (local, **arg, arg.layout.ty)).collect::<Vec<_>>()
                         );
-                        trace!("args: {:#?}", args);
                         let local = arg_locals.nth(1).unwrap();
                         for (i, &op) in args.into_iter().enumerate() {
                             let dest = self.eval_place(&mir::Place::Local(local).field(
@@ -319,10 +319,10 @@ impl<'a, 'mir, 'tcx, M: Machine<'mir, 'tcx>> EvalContext<'a, 'mir, 'tcx, M> {
                 let mut arg_locals = self.frame().mir.args_iter();
                 trace!("ABI: {:?}", sig.abi);
                 trace!(
-                    "arg_locals: {:#?}",
-                    self.frame().mir.args_iter().collect::<Vec<_>>()
+                    "args: {:#?}",
+                    self.frame().mir.args_iter().zip(args.iter())
+                        .map(|(local, arg)| (local, **arg, arg.layout.ty)).collect::<Vec<_>>()
                 );
-                trace!("args: {:#?}", args);
                 match sig.abi {
                     Abi::RustCall => {
                         assert_eq!(args.len(), 2);