Merge pull request #3728 from obscuren/format-trace

core/evm, core/vm: improved evm trace output

cmd/evm/main.go

@@ -66,10 +66,6 @@ var (
 		Name:  "input",
 		Usage: "input for the EVM",
 	}
-	SysStatFlag = cli.BoolFlag{
-		Name:  "sysstat",
-		Usage: "display system stats",
-	}
 	VerbosityFlag = cli.IntFlag{
 		Name:  "verbosity",
 		Usage: "sets the verbosity level",
@@ -89,7 +85,6 @@ func init() {
 		CreateFlag,
 		DebugFlag,
 		VerbosityFlag,
-		SysStatFlag,
 		CodeFlag,
 		CodeFileFlag,
 		GasFlag,

cmd/evm/runner.go

@@ -25,6 +25,7 @@ import (
 
 	goruntime "runtime"
 
+	"github.com/ethereum/go-ethereum/cmd/evm/internal/compiler"
 	"github.com/ethereum/go-ethereum/cmd/utils"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/state"
@@ -53,7 +54,6 @@ func runCmd(ctx *cli.Context) error {
 		statedb, _ = state.New(common.Hash{}, db)
 		sender     = common.StringToAddress("sender")
 		logger     = vm.NewStructLogger(nil)
-		tstart     = time.Now()
 	)
 	statedb.CreateAccount(sender)
 
@@ -62,7 +62,18 @@ func runCmd(ctx *cli.Context) error {
 		ret  []byte
 		err  error
 	)
-	if ctx.GlobalString(CodeFlag.Name) != "" {
+	if fn := ctx.Args().First(); len(fn) > 0 {
+		src, err := ioutil.ReadFile(fn)
+		if err != nil {
+			return err
+		}
+
+		bin, err := compiler.Compile(fn, src, false)
+		if err != nil {
+			return err
+		}
+		code = common.Hex2Bytes(bin)
+	} else if ctx.GlobalString(CodeFlag.Name) != "" {
 		code = common.Hex2Bytes(ctx.GlobalString(CodeFlag.Name))
 	} else {
 		var hexcode []byte
@@ -84,59 +95,54 @@ func runCmd(ctx *cli.Context) error {
 		code = common.Hex2Bytes(string(bytes.TrimRight(hexcode, "\n")))
 	}
 
+	runtimeConfig := runtime.Config{
+		Origin:   sender,
+		State:    statedb,
+		GasLimit: ctx.GlobalUint64(GasFlag.Name),
+		GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
+		Value:    utils.GlobalBig(ctx, ValueFlag.Name),
+		EVMConfig: vm.Config{
+			Tracer:             logger,
+			Debug:              ctx.GlobalBool(DebugFlag.Name),
+			DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
+		},
+	}
+
+	tstart := time.Now()
 	if ctx.GlobalBool(CreateFlag.Name) {
 		input := append(code, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name))...)
-		ret, _, err = runtime.Create(input, &runtime.Config{
-			Origin:   sender,
-			State:    statedb,
-			GasLimit: ctx.GlobalUint64(GasFlag.Name),
-			GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
-			Value:    utils.GlobalBig(ctx, ValueFlag.Name),
-			EVMConfig: vm.Config{
-				Tracer:             logger,
-				Debug:              ctx.GlobalBool(DebugFlag.Name),
-				DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
-			},
-		})
+		ret, _, err = runtime.Create(input, &runtimeConfig)
 	} else {
 		receiver := common.StringToAddress("receiver")
 		statedb.SetCode(receiver, code)
 
-		ret, err = runtime.Call(receiver, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name)), &runtime.Config{
-			Origin:   sender,
-			State:    statedb,
-			GasLimit: ctx.GlobalUint64(GasFlag.Name),
-			GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
-			Value:    utils.GlobalBig(ctx, ValueFlag.Name),
-			EVMConfig: vm.Config{
-				Tracer:             logger,
-				Debug:              ctx.GlobalBool(DebugFlag.Name),
-				DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
-			},
-		})
+		ret, err = runtime.Call(receiver, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name)), &runtimeConfig)
 	}
-	vmdone := time.Since(tstart)
+	execTime := time.Since(tstart)
 
 	if ctx.GlobalBool(DumpFlag.Name) {
 		statedb.Commit(true)
 		fmt.Println(string(statedb.Dump()))
 	}
-	vm.StdErrFormat(logger.StructLogs())
 
-	if ctx.GlobalBool(SysStatFlag.Name) {
+	if ctx.GlobalBool(DebugFlag.Name) {
+		fmt.Fprintln(os.Stderr, "#### TRACE ####")
+		vm.WriteTrace(os.Stderr, logger.StructLogs())
+		fmt.Fprintln(os.Stderr, "#### LOGS ####")
+		vm.WriteLogs(os.Stderr, statedb.Logs())
+
 		var mem goruntime.MemStats
 		goruntime.ReadMemStats(&mem)
-		fmt.Printf("vm took %v\n", vmdone)
-		fmt.Printf(`alloc:      %d
-tot alloc:  %d
-no. malloc: %d
-heap alloc: %d
-heap objs:  %d
-num gc:     %d
-`, mem.Alloc, mem.TotalAlloc, mem.Mallocs, mem.HeapAlloc, mem.HeapObjects, mem.NumGC)
+		fmt.Fprintf(os.Stderr, `evm execution time: %v
+heap objects:       %d
+allocations:        %d
+total allocations:  %d
+GC calls:           %d
+
+`, execTime, mem.HeapObjects, mem.Alloc, mem.TotalAlloc, mem.NumGC)
 	}
 
-	fmt.Printf("OUT: 0x%x", ret)
+	fmt.Printf("0x%x", ret)
 	if err != nil {
 		fmt.Printf(" error: %v", err)
 	}

core/vm/logger.go

@@ -19,11 +19,12 @@ package vm
 import (
 	"encoding/hex"
 	"fmt"
+	"io"
 	"math/big"
-	"os"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/math"
+	"github.com/ethereum/go-ethereum/core/types"
 )
 
 type Storage map[common.Hash]common.Hash
@@ -168,29 +169,38 @@ func (l *StructLogger) StructLogs() []StructLog {
 	return l.logs
 }
 
-// StdErrFormat formats a slice of StructLogs to human readable format
-func StdErrFormat(logs []StructLog) {
-	fmt.Fprintf(os.Stderr, "VM STAT %d OPs\n", len(logs))
+// WriteTrace writes a formatted trace to the given writer
+func WriteTrace(writer io.Writer, logs []StructLog) {
 	for _, log := range logs {
-		fmt.Fprintf(os.Stderr, "PC %08d: %s GAS: %v COST: %v", log.Pc, log.Op, log.Gas, log.GasCost)
+		fmt.Fprintf(writer, "%-10spc=%08d gas=%v cost=%v", log.Op, log.Pc, log.Gas, log.GasCost)
 		if log.Err != nil {
-			fmt.Fprintf(os.Stderr, " ERROR: %v", log.Err)
+			fmt.Fprintf(writer, " ERROR: %v", log.Err)
 		}
-		fmt.Fprintf(os.Stderr, "\n")
-
-		fmt.Fprintln(os.Stderr, "STACK =", len(log.Stack))
+		fmt.Fprintf(writer, "\n")
 
 		for i := len(log.Stack) - 1; i >= 0; i-- {
-			fmt.Fprintf(os.Stderr, "%04d: %x\n", len(log.Stack)-i-1, math.PaddedBigBytes(log.Stack[i], 32))
+			fmt.Fprintf(writer, "%08d  %x\n", len(log.Stack)-i-1, math.PaddedBigBytes(log.Stack[i], 32))
 		}
 
-		fmt.Fprintln(os.Stderr, "MEM =", len(log.Memory))
-		fmt.Fprintln(os.Stderr, hex.Dump(log.Memory))
+		fmt.Fprint(writer, hex.Dump(log.Memory))
 
-		fmt.Fprintln(os.Stderr, "STORAGE =", len(log.Storage))
 		for h, item := range log.Storage {
-			fmt.Fprintf(os.Stderr, "%x: %x\n", h, item)
+			fmt.Fprintf(writer, "%x: %x\n", h, item)
+		}
+		fmt.Fprintln(writer)
+	}
+}
+
+// WriteLogs writes vm logs in a readable format to the given writer
+func WriteLogs(writer io.Writer, logs []*types.Log) {
+	for _, log := range logs {
+		fmt.Fprintf(writer, "LOG%d: %x bn=%d txi=%x\n", len(log.Topics), log.Address, log.BlockNumber, log.TxIndex)
+
+		for i, topic := range log.Topics {
+			fmt.Fprintf(writer, "%08d  %x\n", i, topic)
 		}
-		fmt.Fprintln(os.Stderr)
+
+		fmt.Fprint(writer, hex.Dump(log.Data))
+		fmt.Fprintln(writer)
 	}
 }