From 8035146ace36fc924eae64c014bc3ebfd6989d39 Mon Sep 17 00:00:00 2001 From: Jacek Glen Date: Mon, 30 May 2022 22:22:35 +0200 Subject: [PATCH 1/2] Add total measurement option --- core/vm/interpreter.go | 77 ++++++++++++-- core/vm/runtime/env.go | 11 +- core/vm/time.go | 9 ++ tests/imapp_measure/imapp_measurement | 147 ++++++++++++++++++++++++++ 4 files changed, 232 insertions(+), 12 deletions(-) create mode 100644 core/vm/time.go create mode 100644 tests/imapp_measure/imapp_measurement diff --git a/core/vm/interpreter.go b/core/vm/interpreter.go index 01914913238..3625e1215f9 100644 --- a/core/vm/interpreter.go +++ b/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,19 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( switch { case err != nil: + in.cfg.Instrumenter.tick() return nil, err case operation.reverts: + in.cfg.Instrumenter.tick() return res, ErrExecutionReverted case operation.halts: + in.cfg.Instrumenter.tick() return res, nil case !operation.jumps: pc++ } } + in.cfg.Instrumenter.tick() return nil, nil } diff --git a/core/vm/runtime/env.go b/core/vm/runtime/env.go index bf514f74e03..31c6488b70a 100644 --- a/core/vm/runtime/env.go +++ b/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(), diff --git a/core/vm/time.go b/core/vm/time.go new file mode 100644 index 00000000000..a5c8bfa3620 --- /dev/null +++ b/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 diff --git a/tests/imapp_measure/imapp_measurement b/tests/imapp_measure/imapp_measurement new file mode 100644 index 00000000000..339e601c8ef --- /dev/null +++ b/tests/imapp_measure/imapp_measurement @@ -0,0 +1,147 @@ +package main + +import ( + "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/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", 1, "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) + } + + cfg := new(runtime.Config) + setDefaults(cfg) + // from `github.com/ethereum/go-ethereum/core/vm/runtime/runtime.go:109` + cfg.State, _ = state.New(common.Hash{}, state.NewDatabase(rawdb.NewMemoryDatabase()), nil) + + // 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)) + + // Warm-up. **NOTE** we're keeping tracing on during warm-up, otherwise measurements are off + cfg.EVMConfig.Debug = false + cfg.EVMConfig.Instrumenter = vm.NewInstrumenterLogger() + retWarmUp, _, errWarmUp := runtime.Execute(bytecode, calldata, cfg) + // End warm-up + + sampleStart := time.Now() + for i := 0; i < sampleSize; i++ { + if mode == "total" { + MeasureTotal(cfg, bytecode, printEach, printCSV, i) + } + } + + 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) + + if err != nil { + fmt.Fprintln(os.Stderr, err) + } + + if printCSV { + vm.WriteCSVInstrumentationTotal(os.Stdout, cfg.EVMConfig.Instrumenter, sampleId) + } +} + +// copied directly from github.com/ethereum/go-ethereum/core/vm/runtime/runtime.go +// so that we skip this in measured code +func setDefaults(cfg *runtime.Config) { + if cfg.ChainConfig == nil { + cfg.ChainConfig = ¶ms.ChainConfig{ + ChainID: big.NewInt(1), + HomesteadBlock: new(big.Int), + DAOForkBlock: new(big.Int), + DAOForkSupport: false, + EIP150Block: new(big.Int), + EIP150Hash: common.Hash{}, + EIP155Block: new(big.Int), + EIP158Block: 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), + } + } + + 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(big.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 From 61f1e04a4e62f880df32fe89232800cfb143c5ad Mon Sep 17 00:00:00 2001 From: Jacek Glen Date: Tue, 31 May 2022 09:45:28 +0200 Subject: [PATCH 2/2] Measurement fixes --- core/vm/interpreter.go | 28 +++++++-- ...imapp_measurement => imapp_measurement.go} | 62 ++++++++++++------- 2 files changed, 62 insertions(+), 28 deletions(-) rename tests/imapp_measure/{imapp_measurement => imapp_measurement.go} (71%) diff --git a/core/vm/interpreter.go b/core/vm/interpreter.go index 3625e1215f9..cf64e6a3e90 100644 --- a/core/vm/interpreter.go +++ b/core/vm/interpreter.go @@ -383,19 +383,39 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( switch { case err != nil: - in.cfg.Instrumenter.tick() + // BEGIN COPY PASTE BLOCK + 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 return nil, err case operation.reverts: - in.cfg.Instrumenter.tick() + // BEGIN COPY PASTE BLOCK + 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 return res, ErrExecutionReverted case operation.halts: - in.cfg.Instrumenter.tick() + // BEGIN COPY PASTE BLOCK + 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 return res, nil case !operation.jumps: pc++ } } - in.cfg.Instrumenter.tick() + // BEGIN COPY PASTE BLOCK + 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 return nil, nil } diff --git a/tests/imapp_measure/imapp_measurement b/tests/imapp_measure/imapp_measurement.go similarity index 71% rename from tests/imapp_measure/imapp_measurement rename to tests/imapp_measure/imapp_measurement.go index 339e601c8ef..92c27c52bea 100644 --- a/tests/imapp_measure/imapp_measurement +++ b/tests/imapp_measure/imapp_measurement.go @@ -1,6 +1,7 @@ package main import ( + "context" "flag" "fmt" "math" @@ -16,6 +17,7 @@ import ( "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" @@ -26,7 +28,7 @@ var calldata []byte func main() { bytecodePtr := flag.String("bytecode", "", "EVM bytecode to execute and measure") - sampleSizePtr := flag.Int("sampleSize", 1, "Size of the sample - number of measured repetitions of execution") + 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") @@ -44,10 +46,18 @@ func main() { os.Exit(1) } + fmt.Fprintln(os.Stderr, "Config: ", *bytecodePtr) cfg := new(runtime.Config) setDefaults(cfg) - // from `github.com/ethereum/go-ethereum/core/vm/runtime/runtime.go:109` - cfg.State, _ = state.New(common.Hash{}, state.NewDatabase(rawdb.NewMemoryDatabase()), nil) + + 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) @@ -55,12 +65,14 @@ func main() { // which we'll be using to generate arguments for those OPCODEs. calldata = []byte(strings.Repeat("{", 1<<17)) - // Warm-up. **NOTE** we're keeping tracing on during warm-up, otherwise measurements are off cfg.EVMConfig.Debug = false cfg.EVMConfig.Instrumenter = vm.NewInstrumenterLogger() - retWarmUp, _, errWarmUp := runtime.Execute(bytecode, calldata, cfg) + 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" { @@ -68,6 +80,8 @@ func main() { } } + fmt.Fprintln(os.Stderr, "Done") + sampleDuration := time.Since(sampleStart) if errWarmUp != nil { @@ -76,14 +90,13 @@ func main() { 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) + _, _, err := runtime.Execute(bytecode, calldata, cfg, 0) if err != nil { fmt.Fprintln(os.Stderr, err) @@ -94,26 +107,26 @@ func MeasureTotal(cfg *runtime.Config, bytecode []byte, printEach bool, printCSV } } -// copied directly from github.com/ethereum/go-ethereum/core/vm/runtime/runtime.go +// 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 = ¶ms.ChainConfig{ - ChainID: big.NewInt(1), - HomesteadBlock: new(big.Int), - DAOForkBlock: new(big.Int), - DAOForkSupport: false, - EIP150Block: new(big.Int), - EIP150Hash: common.Hash{}, - EIP155Block: new(big.Int), - EIP158Block: 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), + 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), } } @@ -130,7 +143,7 @@ func setDefaults(cfg *runtime.Config) { cfg.GasPrice = new(big.Int) } if cfg.Value == nil { - cfg.Value = new(big.Int) + cfg.Value = new(uint256.Int) } if cfg.BlockNumber == nil { cfg.BlockNumber = new(big.Int) @@ -140,6 +153,7 @@ func setDefaults(cfg *runtime.Config) { return common.BytesToHash(crypto.Keccak256([]byte(new(big.Int).SetUint64(n).String()))) } } + } // runtimeNano returns the current value of the runtime clock in nanoseconds.