Merge pull request #1228 from obscuren/vm-optimisations

core/vm: optimisations

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)
 }

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)

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

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)

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)
 	}

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
 //

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))
 

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

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)

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)
+	}
+}

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)

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
 }

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())
 
-	return self
-}
+		object := context.self.(*state.StateObject)
+		storage := make(map[common.Hash][]byte)
+		object.EachStorage(func(k, v []byte) {
+			storage[common.BytesToHash(k)] = v
+		})
 
-func (self *Vm) Endl() VirtualMachine {
-	if self.debug {
-		glog.V(0).Infoln(self.logStr)
-		self.logStr = ""
+		self.env.AddStructLog(StructLog{pc, op, new(big.Int).Set(gas), cost, mem, stck, storage})
 	}
-
-	return self
 }
 
+// Environment returns the current workable state of the VM
 func (self *Vm) Env() Environment {
 	return self.env
 }

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)
+}

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 {

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)