Wallclock total

core/vm/interpreter.go

@@ -17,7 +17,9 @@
 package vm
 
 import (
+	"fmt"
 	"hash"
+	"io"
 	"sync/atomic"
 
 	"github.com/ledgerwatch/erigon/common"
@@ -26,17 +28,70 @@ import (
 	"github.com/ledgerwatch/log/v3"
 )
 
+type InstrumenterLog struct {
+	Pc          uint64 `json:"pc"`
+	Op          OpCode `json:"op"`
+	TimeNs      int64  `json:"timeNs"`
+	TimerTimeNs int64  `json:"timerTimeNs"`
+}
+
+type InstrumenterLogger struct {
+	Logs      []InstrumenterLog
+	StartTime int64
+
+	// worker fields, just to avoid reallocation of local vars
+	OpCodeDuration         int64
+	TimerDuration          int64
+	TotalExecutionDuration int64
+	Log                    InstrumenterLog
+}
+
+// NewInstrumenterLogger returns a new logger
+func NewInstrumenterLogger() *InstrumenterLogger {
+	logger := &InstrumenterLogger{}
+	return logger
+}
+
+// WriteTrace writes a formatted trace to the given writer
+func WriteInstrumentation(writer io.Writer, logs []InstrumenterLog) {
+	for _, log := range logs {
+		fmt.Fprintf(writer, "%-16spc=%08d time_ns=%v timer_time_ns=%v", log.Op, log.Pc, log.TimeNs, log.TimerTimeNs)
+		fmt.Fprintln(writer)
+	}
+}
+
+func WriteCSVInstrumentationTotal(writer io.Writer, instrumenter *InstrumenterLogger, runId int) {
+	fmt.Fprintf(writer, "%v,%v,%v", runId, instrumenter.TotalExecutionDuration, instrumenter.TimerDuration)
+	fmt.Fprintln(writer)
+}
+
+func WriteCSVInstrumentationAll(writer io.Writer, logs []InstrumenterLog, runId int) {
+	// CSV header must be in sync with these fields here :(, but it's in measurements.py
+	for instructionId, log := range logs {
+		fmt.Fprintf(writer, "%v,%v,%v,%v", runId, instructionId, log.TimeNs, log.TimerTimeNs)
+		fmt.Fprintln(writer)
+	}
+}
+
+func (instrumenter *InstrumenterLogger) tick() {
+	instrumenter.TotalExecutionDuration = runtimeNano()
+	instrumenter.TimerDuration = runtimeNano()
+	instrumenter.TimerDuration -= instrumenter.TotalExecutionDuration
+	instrumenter.TotalExecutionDuration -= instrumenter.StartTime
+}
+
 // Config are the configuration options for the Interpreter
 type Config struct {
 	Debug         bool   // Enables debugging
 	Tracer        Tracer // Opcode logger
-	NoRecursion   bool   // Disables call, callcode, delegate call and create
-	NoBaseFee     bool   // Forces the EIP-1559 baseFee to 0 (needed for 0 price calls)
-	SkipAnalysis  bool   // Whether we can skip jumpdest analysis based on the checked history
-	TraceJumpDest bool   // Print transaction hashes where jumpdest analysis was useful
-	NoReceipts    bool   // Do not calculate receipts
-	ReadOnly      bool   // Do no perform any block finalisation
-	EnableTEMV    bool   // true if execution with TEVM enable flag
+	Instrumenter  *InstrumenterLogger
+	NoRecursion   bool // Disables call, callcode, delegate call and create
+	NoBaseFee     bool // Forces the EIP-1559 baseFee to 0 (needed for 0 price calls)
+	SkipAnalysis  bool // Whether we can skip jumpdest analysis based on the checked history
+	TraceJumpDest bool // Print transaction hashes where jumpdest analysis was useful
+	NoReceipts    bool // Do not calculate receipts
+	ReadOnly      bool // Do no perform any block finalisation
+	EnableTEMV    bool // true if execution with TEVM enable flag
 
 	ExtraEips []int // Additional EIPS that are to be enabled
 }
@@ -232,6 +287,10 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) (
 			}
 		}()
 	}
+
+	// start timer
+	in.cfg.Instrumenter.StartTime = runtimeNano()
+
 	// The Interpreter main run loop (contextual). This loop runs until either an
 	// explicit STOP, RETURN or SELFDESTRUCT is executed, an error occurred during
 	// the execution of one of the operations or until the done flag is set by the
@@ -324,15 +383,39 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) (
 
 		switch {
 		case err != nil:
+			// BEGIN COPY PASTE BLOCK <shame>
+			in.cfg.Instrumenter.TotalExecutionDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration -= in.cfg.Instrumenter.TotalExecutionDuration
+			in.cfg.Instrumenter.TotalExecutionDuration -= in.cfg.Instrumenter.StartTime
+			// END COPY PASTE BLOCK </shame>
 			return nil, err
 		case operation.reverts:
+			// BEGIN COPY PASTE BLOCK <shame>
+			in.cfg.Instrumenter.TotalExecutionDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration -= in.cfg.Instrumenter.TotalExecutionDuration
+			in.cfg.Instrumenter.TotalExecutionDuration -= in.cfg.Instrumenter.StartTime
+			// END COPY PASTE BLOCK </shame>
 			return res, ErrExecutionReverted
 		case operation.halts:
+			// BEGIN COPY PASTE BLOCK <shame>
+			in.cfg.Instrumenter.TotalExecutionDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration = runtimeNano()
+			in.cfg.Instrumenter.TimerDuration -= in.cfg.Instrumenter.TotalExecutionDuration
+			in.cfg.Instrumenter.TotalExecutionDuration -= in.cfg.Instrumenter.StartTime
+			// END COPY PASTE BLOCK </shame>
 			return res, nil
 		case !operation.jumps:
 			pc++
 		}
 	}
+	// BEGIN COPY PASTE BLOCK <shame>
+	in.cfg.Instrumenter.TotalExecutionDuration = runtimeNano()
+	in.cfg.Instrumenter.TimerDuration = runtimeNano()
+	in.cfg.Instrumenter.TimerDuration -= in.cfg.Instrumenter.TotalExecutionDuration
+	in.cfg.Instrumenter.TotalExecutionDuration -= in.cfg.Instrumenter.StartTime
+	// END COPY PASTE BLOCK </shame>
 	return nil, nil
 }
 

core/vm/runtime/env.go

@@ -17,9 +17,9 @@
 package runtime
 
 import (
+	"github.com/ledgerwatch/erigon/common"
 	"github.com/ledgerwatch/erigon/core"
 	"github.com/ledgerwatch/erigon/core/vm"
-	"github.com/ledgerwatch/erigon/ethdb"
 )
 
 func NewEnv(cfg *Config) *vm.EVM {
@@ -29,10 +29,11 @@ func NewEnv(cfg *Config) *vm.EVM {
 	}
 
 	blockContext := vm.BlockContext{
-		CanTransfer:     core.CanTransfer,
-		Transfer:        core.Transfer,
-		GetHash:         cfg.GetHashFn,
-		ContractHasTEVM: ethdb.GetHasTEVM(cfg.kv),
+		CanTransfer: core.CanTransfer,
+		Transfer:    core.Transfer,
+		GetHash:     cfg.GetHashFn,
+		//imapp_benchmark: disable TEVM for all storages
+		ContractHasTEVM: func(common.Hash) (bool, error) { return false, nil },
 		Coinbase:        cfg.Coinbase,
 		BlockNumber:     cfg.BlockNumber.Uint64(),
 		Time:            cfg.Time.Uint64(),

core/vm/time.go

@@ -0,0 +1,9 @@
+package vm
+
+// this portion ensures that we have access to the least-overhead timer
+
+import _ "unsafe"
+
+// runtimeNano returns the current value of the runtime clock in nanoseconds.
+//go:linkname runtimeNano runtime.nanotime
+func runtimeNano() int64

tests/imapp_measure/imapp_measurement.go

@@ -0,0 +1,161 @@
+package main
+
+import (
+	"context"
+	"flag"
+	"fmt"
+	"math"
+	"math/big"
+	"os"
+	go_runtime "runtime"
+	"strings"
+	"time"
+
+	_ "unsafe"
+
+	"github.com/holiman/uint256"
+	"github.com/ledgerwatch/erigon-lib/kv/memdb"
+	"github.com/ledgerwatch/erigon/common"
+	"github.com/ledgerwatch/erigon/core/state"
+	"github.com/ledgerwatch/erigon/core/vm"
+	"github.com/ledgerwatch/erigon/core/vm/runtime"
+	"github.com/ledgerwatch/erigon/crypto"
+	"github.com/ledgerwatch/erigon/params"
+)
+
+var calldata []byte
+
+func main() {
+
+	bytecodePtr := flag.String("bytecode", "", "EVM bytecode to execute and measure")
+	sampleSizePtr := flag.Int("sampleSize", 10, "Size of the sample - number of measured repetitions of execution")
+	printEachPtr := flag.Bool("printEach", true, "If false, printing of each execution time is skipped")
+	printCSVPtr := flag.Bool("printCSV", false, "If true, will print a CSV with standard results to STDOUT")
+	modePtr := flag.String("mode", "total", "Measurement mode. Available options: all, total, trace")
+
+	flag.Parse()
+
+	bytecode := common.Hex2Bytes(*bytecodePtr)
+	sampleSize := *sampleSizePtr
+	printEach := *printEachPtr
+	printCSV := *printCSVPtr
+	mode := *modePtr
+
+	if mode != "total" {
+		fmt.Fprintln(os.Stderr, "Invalid measurement mode: ", mode)
+		os.Exit(1)
+	}
+
+	fmt.Fprintln(os.Stderr, "Config: ", *bytecodePtr)
+	cfg := new(runtime.Config)
+	setDefaults(cfg)
+
+	fmt.Fprintln(os.Stderr, "db")
+	db := memdb.New()
+	tx, err := db.BeginRw(context.Background())
+	if err != nil {
+		fmt.Println(err)
+		return
+	}
+	cfg.State = state.New(state.NewDbStateReader(tx))
+
+	// Initialize some constant calldata of 128KB, 2^17 bytes.
+	// This means, if we offset between 0th and 2^16th byte, we can fetch between 0 and 2^16 bytes (64KB)
+	// In consequence, we need args to memory-copying OPCODEs to be between 0 and 2^16, 2^16 fits in a PUSH3,
+	// which we'll be using to generate arguments for those OPCODEs.
+	calldata = []byte(strings.Repeat("{", 1<<17))
+
+	cfg.EVMConfig.Debug = false
+	cfg.EVMConfig.Instrumenter = vm.NewInstrumenterLogger()
+	fmt.Fprintln(os.Stderr, "warmup")
+	retWarmUp, _, errWarmUp := runtime.Execute(bytecode, calldata, cfg, 0)
+	// End warm-up
+
+	fmt.Fprintln(os.Stderr, "loop count: ", sampleSize)
+
+	sampleStart := time.Now()
+	for i := 0; i < sampleSize; i++ {
+		if mode == "total" {
+			MeasureTotal(cfg, bytecode, printEach, printCSV, i)
+		}
+	}
+
+	fmt.Fprintln(os.Stderr, "Done")
+
+	sampleDuration := time.Since(sampleStart)
+
+	if errWarmUp != nil {
+		fmt.Fprintln(os.Stderr, errWarmUp)
+	}
+	fmt.Fprintln(os.Stderr, "Program: ", *bytecodePtr)
+	fmt.Fprintln(os.Stderr, "Return:", retWarmUp)
+	fmt.Fprintln(os.Stderr, "Sample duration:", sampleDuration)
+}
+
+func MeasureTotal(cfg *runtime.Config, bytecode []byte, printEach bool, printCSV bool, sampleId int) {
+	cfg.EVMConfig.Instrumenter = vm.NewInstrumenterLogger()
+	go_runtime.GC()
+
+	_, _, err := runtime.Execute(bytecode, calldata, cfg, 0)
+
+	if err != nil {
+		fmt.Fprintln(os.Stderr, err)
+	}
+
+	if printCSV {
+		vm.WriteCSVInstrumentationTotal(os.Stdout, cfg.EVMConfig.Instrumenter, sampleId)
+	}
+}
+
+// copied directly from github.com/ledgerwatch/erigon/core/vm/runtime/runtime.go
+// so that we skip this in measured code
+func setDefaults(cfg *runtime.Config) {
+	if cfg.ChainConfig == nil {
+		cfg.ChainConfig = &params.ChainConfig{
+			ChainID:               big.NewInt(1),
+			HomesteadBlock:        new(big.Int),
+			DAOForkBlock:          new(big.Int),
+			DAOForkSupport:        false,
+			TangerineWhistleBlock: new(big.Int),
+			TangerineWhistleHash:  common.Hash{},
+			SpuriousDragonBlock:   new(big.Int),
+			ByzantiumBlock:        new(big.Int),
+			ConstantinopleBlock:   new(big.Int),
+			PetersburgBlock:       new(big.Int),
+			IstanbulBlock:         new(big.Int),
+			MuirGlacierBlock:      new(big.Int),
+			BerlinBlock:           new(big.Int),
+			LondonBlock:           new(big.Int),
+			ArrowGlacierBlock:     new(big.Int),
+		}
+	}
+
+	if cfg.Difficulty == nil {
+		cfg.Difficulty = new(big.Int)
+	}
+	if cfg.Time == nil {
+		cfg.Time = big.NewInt(time.Now().Unix())
+	}
+	if cfg.GasLimit == 0 {
+		cfg.GasLimit = math.MaxUint64
+	}
+	if cfg.GasPrice == nil {
+		cfg.GasPrice = new(big.Int)
+	}
+	if cfg.Value == nil {
+		cfg.Value = new(uint256.Int)
+	}
+	if cfg.BlockNumber == nil {
+		cfg.BlockNumber = new(big.Int)
+	}
+	if cfg.GetHashFn == nil {
+		cfg.GetHashFn = func(n uint64) common.Hash {
+			return common.BytesToHash(crypto.Keccak256([]byte(new(big.Int).SetUint64(n).String())))
+		}
+	}
+
+}
+
+// runtimeNano returns the current value of the runtime clock in nanoseconds.
+//go:linkname runtimeNano runtime.nanotime
+func runtimeNano() int64