Merge pull request #1228 from obscuren/vm-optimisations

core/vm: optimisations

16 files changed, 200 insertions, 159 deletions

diff --git a/cmd/evm/main.go b/cmd/evm/main.go
index 561f1a943..7c9d27fac 100644
--- a/cmd/evm/main.go
+++ b/cmd/evm/main.go
@@ -59,6 +59,7 @@ func main() {
 
 	logger.AddLogSystem(logger.NewStdLogSystem(os.Stdout, log.LstdFlags, logger.LogLevel(*loglevel)))
 
+	vm.Debug = true
 	db, _ := ethdb.NewMemDatabase()
 	statedb := state.New(common.Hash{}, db)
 	sender := statedb.CreateAccount(common.StringToAddress("sender"))
@@ -80,6 +81,8 @@ func main() {
 		fmt.Println(string(statedb.Dump()))
 	}
 
+	vm.StdErrFormat(vmenv.StructLogs())
+
 	var mem runtime.MemStats
 	runtime.ReadMemStats(&mem)
 	fmt.Printf("vm took %v\n", time.Since(tstart))
@@ -104,6 +107,7 @@ type VMEnv struct {
 	depth int
 	Gas   *big.Int
 	time  int64
+	logs  []vm.StructLog
 }
 
 func NewEnv(state *state.StateDB, transactor common.Address, value *big.Int) *VMEnv {
@@ -133,6 +137,12 @@ func (self *VMEnv) GetHash(n uint64) common.Hash {
 	}
 	return common.Hash{}
 }
+func (self *VMEnv) AddStructLog(log vm.StructLog) {
+	self.logs = append(self.logs, log)
+}
+func (self *VMEnv) StructLogs() []vm.StructLog {
+	return self.logs
+}
 func (self *VMEnv) AddLog(log *state.Log) {
 	self.state.AddLog(log)
 }
diff --git a/cmd/geth/admin.go b/cmd/geth/admin.go
index 4f22110ad..33ef69792 100644
--- a/cmd/geth/admin.go
+++ b/cmd/geth/admin.go
@@ -271,9 +271,12 @@ func (js *jsre) debugBlock(call otto.FunctionCall) otto.Value {
 	}
 
 	tstart := time.Now()
-
 	old := vm.Debug
-	vm.Debug = true
+
+	if len(call.ArgumentList) > 1 {
+		vm.Debug, _ = call.Argument(1).ToBoolean()
+	}
+
 	_, err = js.ethereum.BlockProcessor().RetryProcess(block)
 	if err != nil {
 		fmt.Println(err)
diff --git a/core/block_processor.go b/core/block_processor.go
index 190e72694..3ec3c585f 100644
--- a/core/block_processor.go
+++ b/core/block_processor.go
@@ -151,11 +151,17 @@ func (sm *BlockProcessor) RetryProcess(block *types.Block) (logs state.Logs, err
 		return nil, ParentError(header.ParentHash)
 	}
 	parent := sm.bc.GetBlock(header.ParentHash)
-	if !sm.Pow.Verify(block) {
+
+	// FIXME Change to full header validation. See #1225
+	errch := make(chan bool)
+	go func() { errch <- sm.Pow.Verify(block) }()
+
+	logs, err = sm.processWithParent(block, parent)
+	if !<-errch {
 		return nil, ValidationError("Block's nonce is invalid (= %x)", block.Nonce)
 	}
 
-	return sm.processWithParent(block, parent)
+	return logs, err
 }
 
 // Process block will attempt to process the given block's transactions and applies them
diff --git a/core/chain_manager.go b/core/chain_manager.go
index 6897c453c..be64b54f4 100644
--- a/core/chain_manager.go
+++ b/core/chain_manager.go
@@ -567,6 +567,7 @@ func (self *ChainManager) InsertChain(chain types.Blocks) (int, error) {
 	go verifyNonces(self.pow, chain, nonceQuit, nonceDone)
 	defer close(nonceQuit)
 
+	txcount := 0
 	for i, block := range chain {
 		bstart := time.Now()
 		// Wait for block i's nonce to be verified before processing
@@ -625,6 +626,8 @@ func (self *ChainManager) InsertChain(chain types.Blocks) (int, error) {
 			return i, err
 		}
 
+		txcount += len(block.Transactions())
+
 		cblock := self.currentBlock
 		// Compare the TD of the last known block in the canonical chain to make sure it's greater.
 		// At this point it's possible that a different chain (fork) becomes the new canonical chain.
@@ -683,7 +686,7 @@ func (self *ChainManager) InsertChain(chain types.Blocks) (int, error) {
 	if (stats.queued > 0 || stats.processed > 0 || stats.ignored > 0) && bool(glog.V(logger.Info)) {
 		tend := time.Since(tstart)
 		start, end := chain[0], chain[len(chain)-1]
-		glog.Infof("imported %d block(s) (%d queued %d ignored) in %v. #%v [%x / %x]\n", stats.processed, stats.queued, stats.ignored, tend, end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4])
+		glog.Infof("imported %d block(s) (%d queued %d ignored) including %d txs in %v. #%v [%x / %x]\n", stats.processed, stats.queued, stats.ignored, txcount, tend, end.Number(), start.Hash().Bytes()[:4], end.Hash().Bytes()[:4])
 	}
 
 	go self.eventMux.Post(queueEvent)
diff --git a/core/execution.go b/core/execution.go
index 522c90449..9fb0210de 100644
--- a/core/execution.go
+++ b/core/execution.go
@@ -2,7 +2,6 @@ package core
 
 import (
 	"math/big"
-	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/state"
@@ -49,8 +48,6 @@ func (self *Execution) Create(caller vm.ContextRef) (ret []byte, err error, acco
 }
 
 func (self *Execution) exec(contextAddr *common.Address, code []byte, caller vm.ContextRef) (ret []byte, err error) {
-	start := time.Now()
-
 	env := self.env
 	evm := self.evm
 	if env.Depth() > int(params.CallCreateDepth.Int64()) {
@@ -96,7 +93,6 @@ func (self *Execution) exec(contextAddr *common.Address, code []byte, caller vm.
 	context.SetCallCode(contextAddr, code)
 
 	ret, err = evm.Run(context, self.input)
-	evm.Printf("message call took %v", time.Since(start)).Endl()
 	if err != nil {
 		env.State().Set(snapshot)
 	}
diff --git a/core/state/state_object.go b/core/state/state_object.go
index bfc4ebc6c..6d2455d79 100644
--- a/core/state/state_object.go
+++ b/core/state/state_object.go
@@ -336,6 +336,22 @@ func (self *StateObject) Nonce() uint64 {
 	return self.nonce
 }
 
+func (self *StateObject) EachStorage(cb func(key, value []byte)) {
+	// When iterating over the storage check the cache first
+	for h, v := range self.storage {
+		cb([]byte(h), v.Bytes())
+	}
+
+	it := self.State.trie.Iterator()
+	for it.Next() {
+		// ignore cached values
+		key := self.State.trie.GetKey(it.Key)
+		if _, ok := self.storage[string(key)]; !ok {
+			cb(key, it.Value)
+		}
+	}
+}
+
 //
 // Encoding
 //
diff --git a/core/state_transition.go b/core/state_transition.go
index 7672fa3ff..fedea8021 100644
--- a/core/state_transition.go
+++ b/core/state_transition.go
@@ -223,6 +223,10 @@ func (self *StateTransition) transitionState() (ret []byte, usedGas *big.Int, er
 		return nil, nil, InvalidTxError(err)
 	}
 
+	if vm.Debug {
+		vm.StdErrFormat(vmenv.StructLogs())
+	}
+
 	self.refundGas()
 	self.state.AddBalance(self.coinbase, new(big.Int).Mul(self.gasUsed(), self.gasPrice))
 
diff --git a/core/vm/context.go b/core/vm/context.go
index de03f84f0..e33324b53 100644
--- a/core/vm/context.go
+++ b/core/vm/context.go
@@ -49,13 +49,13 @@ func NewContext(caller ContextRef, object ContextRef, value, gas, price *big.Int
 	return c
 }
 
-func (c *Context) GetOp(n *big.Int) OpCode {
+func (c *Context) GetOp(n uint64) OpCode {
 	return OpCode(c.GetByte(n))
 }
 
-func (c *Context) GetByte(n *big.Int) byte {
-	if n.Cmp(big.NewInt(int64(len(c.Code)))) < 0 {
-		return c.Code[n.Int64()]
+func (c *Context) GetByte(n uint64) byte {
+	if n < uint64(len(c.Code)) {
+		return c.Code[n]
 	}
 
 	return 0
diff --git a/core/vm/environment.go b/core/vm/environment.go
index 282d19578..5c04e7022 100644
--- a/core/vm/environment.go
+++ b/core/vm/environment.go
@@ -8,6 +8,8 @@ import (
 	"github.com/ethereum/go-ethereum/core/state"
 )
 
+// Environment is is required by the virtual machine to get information from
+// it's own isolated environment. For an example see `core.VMEnv`
 type Environment interface {
 	State() *state.StateDB
 
@@ -20,6 +22,8 @@ type Environment interface {
 	GasLimit() *big.Int
 	Transfer(from, to Account, amount *big.Int) error
 	AddLog(*state.Log)
+	AddStructLog(StructLog)
+	StructLogs() []StructLog
 
 	VmType() Type
 
@@ -31,6 +35,18 @@ type Environment interface {
 	Create(me ContextRef, data []byte, gas, price, value *big.Int) ([]byte, error, ContextRef)
 }
 
+// StructLog is emited to the Environment each cycle and lists information about the curent internal state
+// prior to the execution of the statement.
+type StructLog struct {
+	Pc      uint64
+	Op      OpCode
+	Gas     *big.Int
+	GasCost *big.Int
+	Memory  []byte
+	Stack   []*big.Int
+	Storage map[common.Hash][]byte
+}
+
 type Account interface {
 	SubBalance(amount *big.Int)
 	AddBalance(amount *big.Int)
diff --git a/core/vm/logger.go b/core/vm/logger.go
new file mode 100644
index 000000000..96d07dab5
--- /dev/null
+++ b/core/vm/logger.go
@@ -0,0 +1,46 @@
+package vm
+
+import (
+	"fmt"
+	"os"
+	"unicode/utf8"
+
+	"github.com/ethereum/go-ethereum/common"
+)
+
+func StdErrFormat(logs []StructLog) {
+	fmt.Fprintf(os.Stderr, "VM Stats %d ops\n", len(logs))
+	for _, log := range logs {
+		fmt.Fprintf(os.Stderr, "PC %08d: %s GAS: %v COST: %v\n", log.Pc, log.Op, log.Gas, log.GasCost)
+		fmt.Fprintln(os.Stderr, "STACK =", len(log.Stack))
+
+		for i := len(log.Stack) - 1; i >= 0; i-- {
+			fmt.Fprintf(os.Stderr, "%04d: %x\n", len(log.Stack)-i-1, common.LeftPadBytes(log.Stack[i].Bytes(), 32))
+		}
+
+		const maxMem = 10
+		addr := 0
+		fmt.Fprintln(os.Stderr, "MEM =", len(log.Memory))
+		for i := 0; i+16 <= len(log.Memory) && addr < maxMem; i += 16 {
+			data := log.Memory[i : i+16]
+			str := fmt.Sprintf("%04d: % x  ", addr*16, data)
+			for _, r := range data {
+				if r == 0 {
+					str += "."
+				} else if utf8.ValidRune(rune(r)) {
+					str += fmt.Sprintf("%s", string(r))
+				} else {
+					str += "?"
+				}
+			}
+			addr++
+			fmt.Fprintln(os.Stderr, str)
+		}
+
+		fmt.Fprintln(os.Stderr, "STORAGE =", len(log.Storage))
+		for h, item := range log.Storage {
+			fmt.Fprintf(os.Stderr, "%x: %x\n", h, common.LeftPadBytes(item, 32))
+		}
+		fmt.Fprintln(os.Stderr)
+	}
+}
diff --git a/core/vm/stack.go b/core/vm/stack.go
index bb232d0b9..2be5c3dbe 100644
--- a/core/vm/stack.go
+++ b/core/vm/stack.go
@@ -5,7 +5,7 @@ import (
 	"math/big"
 )
 
-func newStack() *stack {
+func newstack() *stack {
 	return &stack{}
 }
 
@@ -14,6 +14,10 @@ type stack struct {
 	ptr  int
 }
 
+func (st *stack) Data() []*big.Int {
+	return st.data[:st.ptr]
+}
+
 func (st *stack) push(d *big.Int) {
 	// NOTE push limit (1024) is checked in baseCheck
 	stackItem := new(big.Int).Set(d)
diff --git a/core/vm/virtual_machine.go b/core/vm/virtual_machine.go
index 6db284f42..1fd1dcd88 100644
--- a/core/vm/virtual_machine.go
+++ b/core/vm/virtual_machine.go
@@ -3,6 +3,4 @@ package vm
 type VirtualMachine interface {
 	Env() Environment
 	Run(context *Context, data []byte) ([]byte, error)
-	Printf(string, ...interface{}) VirtualMachine
-	Endl() VirtualMachine
 }
diff --git a/core/vm/vm.go b/core/vm/vm.go
index 2bd950385..4c0ab0f47 100644
--- a/core/vm/vm.go
+++ b/core/vm/vm.go
@@ -7,16 +7,13 @@ import (
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/state"
 	"github.com/ethereum/go-ethereum/crypto"
-	"github.com/ethereum/go-ethereum/logger/glog"
 	"github.com/ethereum/go-ethereum/params"
 )
 
+// Vm implements VirtualMachine
 type Vm struct {
 	env Environment
 
-	logTy  byte
-	logStr string
-
 	err error
 	// For logging
 	debug bool
@@ -31,13 +28,13 @@ type Vm struct {
 	After func(*Context, error)
 }
 
+// New returns a new Virtual Machine
 func New(env Environment) *Vm {
-	lt := LogTyPretty
-
-	return &Vm{debug: Debug, env: env, logTy: lt, Recoverable: true}
+	return &Vm{env: env, debug: Debug, Recoverable: true}
 }
 
-func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
+// Run loops and evaluates the contract's code with the given input data
+func (self *Vm) Run(context *Context, input []byte) (ret []byte, err error) {
 	self.env.SetDepth(self.env.Depth() + 1)
 	defer self.env.SetDepth(self.env.Depth() - 1)
 
@@ -48,8 +45,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 		price  = context.Price
 	)
 
-	self.Printf("(%d) (%x) %x (code=%d) gas: %v (d) %x", self.env.Depth(), caller.Address().Bytes()[:4], context.Address(), len(code), context.Gas, callData).Endl()
-
 	// User defer pattern to check for an error and, based on the error being nil or not, use all gas and return.
 	defer func() {
 		if self.After != nil {
@@ -57,7 +52,7 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 		}
 
 		if err != nil {
-			self.Printf(" %v", err).Endl()
+
 			// In case of a VM exception (known exceptions) all gas consumed (panics NOT included).
 			context.UseGas(context.Gas)
 
@@ -67,7 +62,7 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 	if context.CodeAddr != nil {
 		if p := Precompiled[context.CodeAddr.Str()]; p != nil {
-			return self.RunPrecompiled(p, callData, context)
+			return self.RunPrecompiled(p, input, context)
 		}
 	}
 
@@ -77,23 +72,24 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 	}
 
 	var (
-		op       OpCode
-		codehash = crypto.Sha3Hash(code)
-		mem      = NewMemory()
-		stack    = newStack()
-		pc       = new(big.Int)
-		statedb  = self.env.State()
-
-		jump = func(from *big.Int, to *big.Int) error {
+		op       OpCode                  // current opcode
+		codehash = crypto.Sha3Hash(code) // codehash is used when doing jump dest caching
+		mem      = NewMemory()           // bound memory
+		stack    = newstack()            // local stack
+		statedb  = self.env.State()      // current state
+		// For optimisation reason we're using uint64 as the program counter.
+		// It's theoretically possible to go above 2^64. The YP defines the PC to be uint256. Pratically much less so feasible.
+		pc = uint64(0) // program counter
+
+		// jump evaluates and checks whether the given jump destination is a valid one
+		// if valid move the `pc` otherwise return an error.
+		jump = func(from uint64, to *big.Int) error {
 			if !context.jumpdests.has(codehash, code, to) {
-				nop := context.GetOp(to)
+				nop := context.GetOp(to.Uint64())
 				return fmt.Errorf("invalid jump destination (%v) %v", nop, to)
 			}
 
-			self.Printf(" ~> %v", to)
-			pc = to
-
-			self.Endl()
+			pc = to.Uint64()
 
 			return nil
 		}
@@ -106,63 +102,56 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 		// Get the memory location of pc
 		op = context.GetOp(pc)
 
-		self.Printf("(pc) %-3d -o- %-14s (m) %-4d (s) %-4d ", pc, op.String(), mem.Len(), stack.len())
+		// calculate the new memory size and gas price for the current executing opcode
 		newMemSize, gas, err := self.calculateGasAndSize(context, caller, op, statedb, mem, stack)
 		if err != nil {
 			return nil, err
 		}
 
-		self.Printf("(g) %-3v (%v)", gas, context.Gas)
+		self.log(pc, op, context.Gas, gas, mem, stack, context)
 
+		// Use the calculated gas. When insufficient gas is present, use all gas and return an
+		// Out Of Gas error
 		if !context.UseGas(gas) {
-			self.Endl()
-
 			tmp := new(big.Int).Set(context.Gas)
 
 			context.UseGas(context.Gas)
 
 			return context.Return(nil), OOG(gas, tmp)
 		}
-
+		// Resize the memory calculated previously
 		mem.Resize(newMemSize.Uint64())
 
 		switch op {
 		case ADD:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v + %v", y, x)
 
 			base.Add(x, y)
 
 			U256(base)
 
-			self.Printf(" = %v", base)
 			// pop result back on the stack
 			stack.push(base)
 		case SUB:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v - %v", x, y)
 
 			base.Sub(x, y)
 
 			U256(base)
 
-			self.Printf(" = %v", base)
 			// pop result back on the stack
 			stack.push(base)
 		case MUL:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v * %v", y, x)
 
 			base.Mul(x, y)
 
 			U256(base)
 
-			self.Printf(" = %v", base)
 			// pop result back on the stack
 			stack.push(base)
 		case DIV:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v / %v", x, y)
 
 			if y.Cmp(common.Big0) != 0 {
 				base.Div(x, y)
@@ -170,14 +159,11 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 			U256(base)
 
-			self.Printf(" = %v", base)
 			// pop result back on the stack
 			stack.push(base)
 		case SDIV:
 			x, y := S256(stack.pop()), S256(stack.pop())
 
-			self.Printf(" %v / %v", x, y)
-
 			if y.Cmp(common.Big0) == 0 {
 				base.Set(common.Big0)
 			} else {
@@ -193,13 +179,10 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				U256(base)
 			}
 
-			self.Printf(" = %v", base)
 			stack.push(base)
 		case MOD:
 			x, y := stack.pop(), stack.pop()
 
-			self.Printf(" %v %% %v", x, y)
-
 			if y.Cmp(common.Big0) == 0 {
 				base.Set(common.Big0)
 			} else {
@@ -208,13 +191,10 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 			U256(base)
 
-			self.Printf(" = %v", base)
 			stack.push(base)
 		case SMOD:
 			x, y := S256(stack.pop()), S256(stack.pop())
 
-			self.Printf(" %v %% %v", x, y)
-
 			if y.Cmp(common.Big0) == 0 {
 				base.Set(common.Big0)
 			} else {
@@ -230,20 +210,15 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				U256(base)
 			}
 
-			self.Printf(" = %v", base)
 			stack.push(base)
 
 		case EXP:
 			x, y := stack.pop(), stack.pop()
 
-			self.Printf(" %v ** %v", x, y)
-
 			base.Exp(x, y, Pow256)
 
 			U256(base)
 
-			self.Printf(" = %v", base)
-
 			stack.push(base)
 		case SIGNEXTEND:
 			back := stack.pop()
@@ -260,15 +235,13 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 				num = U256(num)
 
-				self.Printf(" = %v", num)
-
 				stack.push(num)
 			}
 		case NOT:
 			stack.push(U256(new(big.Int).Not(stack.pop())))
 		case LT:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v < %v", x, y)
+
 			// x < y
 			if x.Cmp(y) < 0 {
 				stack.push(common.BigTrue)
@@ -277,7 +250,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			}
 		case GT:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v > %v", x, y)
 
 			// x > y
 			if x.Cmp(y) > 0 {
@@ -288,7 +260,7 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 		case SLT:
 			x, y := S256(stack.pop()), S256(stack.pop())
-			self.Printf(" %v < %v", x, y)
+
 			// x < y
 			if x.Cmp(S256(y)) < 0 {
 				stack.push(common.BigTrue)
@@ -297,7 +269,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			}
 		case SGT:
 			x, y := S256(stack.pop()), S256(stack.pop())
-			self.Printf(" %v > %v", x, y)
 
 			// x > y
 			if x.Cmp(y) > 0 {
@@ -308,7 +279,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 		case EQ:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v == %v", y, x)
 
 			// x == y
 			if x.Cmp(y) == 0 {
@@ -326,17 +296,14 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 		case AND:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v & %v", y, x)
 
 			stack.push(base.And(x, y))
 		case OR:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v | %v", x, y)
 
 			stack.push(base.Or(x, y))
 		case XOR:
 			x, y := stack.pop(), stack.pop()
-			self.Printf(" %v ^ %v", x, y)
 
 			stack.push(base.Xor(x, y))
 		case BYTE:
@@ -350,8 +317,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				base.Set(common.BigFalse)
 			}
 
-			self.Printf(" => 0x%x", base.Bytes())
-
 			stack.push(base)
 		case ADDMOD:
 			x := stack.pop()
@@ -365,8 +330,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				base = U256(base)
 			}
 
-			self.Printf(" %v + %v %% %v = %v", x, y, z, base)
-
 			stack.push(base)
 		case MULMOD:
 			x := stack.pop()
@@ -380,8 +343,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				U256(base)
 			}
 
-			self.Printf(" %v + %v %% %v = %v", x, y, z, base)
-
 			stack.push(base)
 
 		case SHA3:
@@ -390,55 +351,45 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 			stack.push(common.BigD(data))
 
-			self.Printf(" => (%v) %x", size, data)
 		case ADDRESS:
 			stack.push(common.Bytes2Big(context.Address().Bytes()))
 
-			self.Printf(" => %x", context.Address())
 		case BALANCE:
 			addr := common.BigToAddress(stack.pop())
 			balance := statedb.GetBalance(addr)
 
 			stack.push(balance)
 
-			self.Printf(" => %v (%x)", balance, addr)
 		case ORIGIN:
 			origin := self.env.Origin()
 
 			stack.push(origin.Big())
 
-			self.Printf(" => %x", origin)
 		case CALLER:
 			caller := context.caller.Address()
 			stack.push(common.Bytes2Big(caller.Bytes()))
 
-			self.Printf(" => %x", caller)
 		case CALLVALUE:
 			stack.push(value)
 
-			self.Printf(" => %v", value)
 		case CALLDATALOAD:
-			data := getData(callData, stack.pop(), common.Big32)
-
-			self.Printf(" => 0x%x", data)
+			data := getData(input, stack.pop(), common.Big32)
 
 			stack.push(common.Bytes2Big(data))
 		case CALLDATASIZE:
-			l := int64(len(callData))
+			l := int64(len(input))
 			stack.push(big.NewInt(l))
 
-			self.Printf(" => %d", l)
 		case CALLDATACOPY:
 			var (
 				mOff = stack.pop()
 				cOff = stack.pop()
 				l    = stack.pop()
 			)
-			data := getData(callData, cOff, l)
+			data := getData(input, cOff, l)
 
 			mem.Set(mOff.Uint64(), l.Uint64(), data)
 
-			self.Printf(" => [%v, %v, %v]", mOff, cOff, l)
 		case CODESIZE, EXTCODESIZE:
 			var code []byte
 			if op == EXTCODESIZE {
@@ -452,7 +403,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			l := big.NewInt(int64(len(code)))
 			stack.push(l)
 
-			self.Printf(" => %d", l)
 		case CODECOPY, EXTCODECOPY:
 			var code []byte
 			if op == EXTCODECOPY {
@@ -472,12 +422,9 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 
 			mem.Set(mOff.Uint64(), l.Uint64(), codeCopy)
 
-			self.Printf(" => [%v, %v, %v] %x", mOff, cOff, l, codeCopy)
 		case GASPRICE:
 			stack.push(context.Price)
 
-			self.Printf(" => %x", context.Price)
-
 		case BLOCKHASH:
 			num := stack.pop()
 
@@ -488,56 +435,47 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				stack.push(common.Big0)
 			}
 
-			self.Printf(" => 0x%x", stack.peek().Bytes())
 		case COINBASE:
 			coinbase := self.env.Coinbase()
 
 			stack.push(coinbase.Big())
 
-			self.Printf(" => 0x%x", coinbase)
 		case TIMESTAMP:
 			time := self.env.Time()
 
 			stack.push(big.NewInt(time))
 
-			self.Printf(" => 0x%x", time)
 		case NUMBER:
 			number := self.env.BlockNumber()
 
 			stack.push(U256(number))
 
-			self.Printf(" => 0x%x", number.Bytes())
 		case DIFFICULTY:
 			difficulty := self.env.Difficulty()
 
 			stack.push(difficulty)
 
-			self.Printf(" => 0x%x", difficulty.Bytes())
 		case GASLIMIT:
-			self.Printf(" => %v", self.env.GasLimit())
 
 			stack.push(self.env.GasLimit())
 
 		case PUSH1, PUSH2, PUSH3, PUSH4, PUSH5, PUSH6, PUSH7, PUSH8, PUSH9, PUSH10, PUSH11, PUSH12, PUSH13, PUSH14, PUSH15, PUSH16, PUSH17, PUSH18, PUSH19, PUSH20, PUSH21, PUSH22, PUSH23, PUSH24, PUSH25, PUSH26, PUSH27, PUSH28, PUSH29, PUSH30, PUSH31, PUSH32:
-			a := big.NewInt(int64(op - PUSH1 + 1))
-			byts := getData(code, new(big.Int).Add(pc, big.NewInt(1)), a)
+			size := uint64(op - PUSH1 + 1)
+			byts := getData(code, new(big.Int).SetUint64(pc+1), new(big.Int).SetUint64(size))
 			// push value to stack
 			stack.push(common.Bytes2Big(byts))
-			pc.Add(pc, a)
+			pc += size
 
-			self.Printf(" => 0x%x", byts)
 		case POP:
 			stack.pop()
 		case DUP1, DUP2, DUP3, DUP4, DUP5, DUP6, DUP7, DUP8, DUP9, DUP10, DUP11, DUP12, DUP13, DUP14, DUP15, DUP16:
 			n := int(op - DUP1 + 1)
 			stack.dup(n)
 
-			self.Printf(" => [%d] 0x%x", n, stack.peek().Bytes())
 		case SWAP1, SWAP2, SWAP3, SWAP4, SWAP5, SWAP6, SWAP7, SWAP8, SWAP9, SWAP10, SWAP11, SWAP12, SWAP13, SWAP14, SWAP15, SWAP16:
 			n := int(op - SWAP1 + 2)
 			stack.swap(n)
 
-			self.Printf(" => [%d]", n)
 		case LOG0, LOG1, LOG2, LOG3, LOG4:
 			n := int(op - LOG0)
 			topics := make([]common.Hash, n)
@@ -550,38 +488,32 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			log := state.NewLog(context.Address(), topics, data, self.env.BlockNumber().Uint64())
 			self.env.AddLog(log)
 
-			self.Printf(" => %v", log)
 		case MLOAD:
 			offset := stack.pop()
 			val := common.BigD(mem.Get(offset.Int64(), 32))
 			stack.push(val)
 
-			self.Printf(" => 0x%x", val.Bytes())
 		case MSTORE:
 			// pop value of the stack
 			mStart, val := stack.pop(), stack.pop()
 			mem.Set(mStart.Uint64(), 32, common.BigToBytes(val, 256))
 
-			self.Printf(" => 0x%x", val)
 		case MSTORE8:
 			off, val := stack.pop().Int64(), stack.pop().Int64()
 
 			mem.store[off] = byte(val & 0xff)
 
-			self.Printf(" => [%v] 0x%x", off, mem.store[off])
 		case SLOAD:
 			loc := common.BigToHash(stack.pop())
 			val := common.Bytes2Big(statedb.GetState(context.Address(), loc))
 			stack.push(val)
 
-			self.Printf(" {0x%x : 0x%x}", loc, val.Bytes())
 		case SSTORE:
 			loc := common.BigToHash(stack.pop())
 			val := stack.pop()
 
 			statedb.SetState(context.Address(), loc, val)
 
-			self.Printf(" {0x%x : 0x%x}", loc, val.Bytes())
 		case JUMP:
 			if err := jump(pc, stack.pop()); err != nil {
 				return nil, err
@@ -599,17 +531,14 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				continue
 			}
 
-			self.Printf(" ~> false")
-
 		case JUMPDEST:
 		case PC:
-			stack.push(pc)
+			stack.push(new(big.Int).SetUint64(pc))
 		case MSIZE:
 			stack.push(big.NewInt(int64(mem.Len())))
 		case GAS:
 			stack.push(context.Gas)
 
-			self.Printf(" => %x", context.Gas)
 		case CREATE:
 
 			var (
@@ -619,14 +548,12 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 				gas          = new(big.Int).Set(context.Gas)
 				addr         common.Address
 			)
-			self.Endl()
 
 			context.UseGas(context.Gas)
 			ret, suberr, ref := self.env.Create(context, input, gas, price, value)
 			if suberr != nil {
 				stack.push(common.BigFalse)
 
-				self.Printf(" (*) 0x0 %v", suberr)
 			} else {
 				// gas < len(ret) * CreateDataGas == NO_CODE
 				dataGas := big.NewInt(int64(len(ret)))
@@ -651,7 +578,6 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			retOffset, retSize := stack.pop(), stack.pop()
 
 			address := common.BigToAddress(addr)
-			self.Printf(" => %x", address).Endl()
 
 			// Get the arguments from the memory
 			args := mem.Get(inOffset.Int64(), inSize.Int64())
@@ -673,47 +599,41 @@ func (self *Vm) Run(context *Context, callData []byte) (ret []byte, err error) {
 			if err != nil {
 				stack.push(common.BigFalse)
 
-				self.Printf("%v").Endl()
 			} else {
 				stack.push(common.BigTrue)
 
 				mem.Set(retOffset.Uint64(), retSize.Uint64(), ret)
 			}
-			self.Printf("resume %x (%v)", context.Address(), context.Gas)
+
 		case RETURN:
 			offset, size := stack.pop(), stack.pop()
 			ret := mem.GetPtr(offset.Int64(), size.Int64())
 
-			self.Printf(" => [%v, %v] (%d) 0x%x", offset, size, len(ret), ret).Endl()
-
 			return context.Return(ret), nil
 		case SUICIDE:
 			receiver := statedb.GetOrNewStateObject(common.BigToAddress(stack.pop()))
 			balance := statedb.GetBalance(context.Address())
 
-			self.Printf(" => (%x) %v", receiver.Address().Bytes()[:4], balance)
-
 			receiver.AddBalance(balance)
 
 			statedb.Delete(context.Address())
 
 			fallthrough
 		case STOP: // Stop the context
-			self.Endl()
 
 			return context.Return(nil), nil
 		default:
-			self.Printf("(pc) %-3v Invalid opcode %x\n", pc, op).Endl()
 
 			return nil, fmt.Errorf("Invalid opcode %x", op)
 		}
 
-		pc.Add(pc, One)
+		pc++
 
-		self.Endl()
 	}
 }
 
+// calculateGasAndSize calculates the required given the opcode and stack items calculates the new memorysize for
+// the operation. This does not reduce gas or resizes the memory.
 func (self *Vm) calculateGasAndSize(context *Context, caller ContextRef, op OpCode, statedb *state.StateDB, mem *Memory, stack *stack) (*big.Int, *big.Int, error) {
 	var (
 		gas                 = new(big.Int)
@@ -855,40 +775,40 @@ func (self *Vm) calculateGasAndSize(context *Context, caller ContextRef, op OpCo
 	return newMemSize, gas, nil
 }
 
-func (self *Vm) RunPrecompiled(p *PrecompiledAccount, callData []byte, context *Context) (ret []byte, err error) {
-	gas := p.Gas(len(callData))
+// RunPrecompile runs and evaluate the output of a precompiled contract defined in contracts.go
+func (self *Vm) RunPrecompiled(p *PrecompiledAccount, input []byte, context *Context) (ret []byte, err error) {
+	gas := p.Gas(len(input))
 	if context.UseGas(gas) {
-		ret = p.Call(callData)
-		self.Printf("NATIVE_FUNC => %x", ret)
-		self.Endl()
+		ret = p.Call(input)
 
 		return context.Return(ret), nil
 	} else {
-		self.Printf("NATIVE_FUNC => failed").Endl()
-
 		tmp := new(big.Int).Set(context.Gas)
 
 		return nil, OOG(gas, tmp)
 	}
 }
 
-func (self *Vm) Printf(format string, v ...interface{}) VirtualMachine {
-	if self.debug {
-		self.logStr += fmt.Sprintf(format, v...)
+// log emits a log event to the environment for each opcode encountered. This is not to be confused with the
+// LOG* opcode.
+func (self *Vm) log(pc uint64, op OpCode, gas, cost *big.Int, memory *Memory, stack *stack, context *Context) {
+	if Debug {
+		mem := make([]byte, len(memory.Data()))
+		copy(mem, memory.Data())
+		stck := make([]*big.Int, len(stack.Data()))
+		copy(stck, stack.Data())
+
+		object := context.self.(*state.StateObject)
+		storage := make(map[common.Hash][]byte)
+		object.EachStorage(func(k, v []byte) {
+			storage[common.BytesToHash(k)] = v
+		})
+
+		self.env.AddStructLog(StructLog{pc, op, new(big.Int).Set(gas), cost, mem, stck, storage})
 	}
-
-	return self
-}
-
-func (self *Vm) Endl() VirtualMachine {
-	if self.debug {
-		glog.V(0).Infoln(self.logStr)
-		self.logStr = ""
-	}
-
-	return self
 }
 
+// Environment returns the current workable state of the VM
 func (self *Vm) Env() Environment {
 	return self.env
 }
diff --git a/core/vm_env.go b/core/vm_env.go
index c439d2946..da862d5c8 100644
--- a/core/vm_env.go
+++ b/core/vm_env.go
@@ -16,6 +16,8 @@ type VMEnv struct {
 	depth int
 	chain *ChainManager
 	typ   vm.Type
+	// structured logging
+	logs []vm.StructLog
 }
 
 func NewEnv(state *state.StateDB, chain *ChainManager, msg Message, block *types.Block) *VMEnv {
@@ -47,6 +49,7 @@ func (self *VMEnv) GetHash(n uint64) common.Hash {
 
 	return common.Hash{}
 }
+
 func (self *VMEnv) AddLog(log *state.Log) {
 	self.state.AddLog(log)
 }
@@ -68,3 +71,11 @@ func (self *VMEnv) Create(me vm.ContextRef, data []byte, gas, price, value *big.
 	exe := NewExecution(self, nil, data, gas, price, value)
 	return exe.Create(me)
 }
+
+func (self *VMEnv) StructLogs() []vm.StructLog {
+	return self.logs
+}
+
+func (self *VMEnv) AddStructLog(log vm.StructLog) {
+	self.logs = append(self.logs, log)
+}
diff --git a/miner/worker.go b/miner/worker.go
index 611445529..bd4bc0e3c 100644
--- a/miner/worker.go
+++ b/miner/worker.go
@@ -270,7 +270,6 @@ func (self *worker) wait() {
 
 func (self *worker) push() {
 	if atomic.LoadInt32(&self.mining) == 1 {
-		self.current.block.Header().GasUsed = self.current.totalUsedGas
 		self.current.block.SetRoot(self.current.state.Root())
 
 		// push new work to agents
@@ -510,6 +509,8 @@ func (self *worker) commitTransactions(transactions types.Transactions) {
 			current.tcount++
 		}
 	}
+
+	self.current.block.Header().GasUsed = self.current.totalUsedGas
 }
 
 func (self *worker) commitTransaction(tx *types.Transaction) error {
diff --git a/tests/helper/vm.go b/tests/helper/vm.go
index 2db2b82c4..e29a2d8ee 100644
--- a/tests/helper/vm.go
+++ b/tests/helper/vm.go
@@ -27,9 +27,8 @@ type Env struct {
 	difficulty *big.Int
 	gasLimit   *big.Int
 
-	logs state.Logs
-
 	vmTest bool
+	logs   []vm.StructLog
 }
 
 func NewEnv(state *state.StateDB) *Env {
@@ -38,6 +37,14 @@ func NewEnv(state *state.StateDB) *Env {
 	}
 }
 
+func (self *Env) StructLogs() []vm.StructLog {
+	return self.logs
+}
+
+func (self *Env) AddStructLog(log vm.StructLog) {
+	self.logs = append(self.logs, log)
+}
+
 func NewEnvFromMap(state *state.StateDB, envValues map[string]string, exeValues map[string]string) *Env {
 	env := NewEnv(state)