more timer

core/blockchain.go

@@ -1820,6 +1820,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 			continue
 		}
 		preProcessDur = time.Since(preprocessBegin)
+
+		varDeclBegin := time.Now()
 		var (
 			err                    error
 			receipts, receiptExist = bc.miningReceiptsCache.Get(block.Hash())
@@ -1830,12 +1832,15 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 		)
 
 		interruptCh := make(chan struct{})
-		pstart := time.Now()
+		varDeclDur := time.Since(varDeclBegin)
 
+		pstart := time.Now()
 		steps := 0
+		var processPrepareDur time.Duration
 		var processDur time.Duration
 		// skip block process if we already have the state, receipts and logs from mining work
 		if !(receiptExist && logExist && stateExist) {
+			processPrepareBegin := time.Now()
 			// Retrieve the parent block and it's state to execute on top
 			parent := it.previous()
 			if parent == nil {
@@ -1869,6 +1874,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 					}(time.Now(), followup, throwaway, vmc)
 				}
 			}
+			processPrepareDur = time.Since(processPrepareBegin)
+
 			steps = 0
 
 			vmcount.Debug = bc.vmConfig.Debug
@@ -1886,6 +1893,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 			// Process block using the parent state as reference point
 			receipts, logs, usedGas, err = bc.processor.Process(block, statedb, *vmcount)
 			processDur = time.Since(processBegin)
+
 			if oldTracer == nil {
 				steps = tracer.Steps()
 				tracer.Reset()
@@ -1908,8 +1916,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 			return it.index, err
 		}
 		validateDur := time.Since(validateStart)
-		vtime := time.Since(vstart)
 
+		vtime := time.Since(vstart)
 		proctime := time.Since(start) // processing + validation
 
 		metricsUpdateStart := time.Now()
@@ -1982,14 +1990,14 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool)
 			ptime, steps, processDur,
 			validateDur, metricsUpdateTime,
 			writeDur, cacheBlockDur, metricsUpdateTime1,
-			preProcessDur, postProcessDur)
+			preProcessDur, postProcessDur, varDeclDur, processPrepareDur)
 
 		postProcessBegin := time.Now()
 		if !setHead {
 			// After merge we expect few side chains. Simply count
 			// all blocks the CL gives us for GC processing time
 			bc.gcproc += proctime
-
+			postProcessDur = time.Since(postProcessBegin)
 			return it.index, nil // Direct block insertion of a single block
 		}
 		switch status {

core/blockchain_insert.go

@@ -39,7 +39,11 @@ const statsReportLimit = 1 * time.Nanosecond
 
 // report prints statistics if some number of blocks have been processed
 // or more than a few seconds have passed since the last message.
-func (st *insertStats) report(chain []*types.Block, index int, dirty common.StorageSize, setHead bool, execTime time.Duration, steps int, processDur time.Duration, validateDur time.Duration, metricUpdateTime1 time.Duration, writeDur time.Duration, cacheDur time.Duration, metricUpdateTime2 time.Duration, preProcessDur time.Duration, postProcessDur time.Duration) {
+func (st *insertStats) report(chain []*types.Block, index int,
+	dirty common.StorageSize, setHead bool, execTime time.Duration, steps int,
+	processDur time.Duration, validateDur time.Duration, metricUpdateTime1 time.Duration,
+	writeDur time.Duration, cacheDur time.Duration, metricUpdateTime2 time.Duration,
+	preProcessDur time.Duration, postProcessDur time.Duration, varDeclDuration time.Duration, processPrepareDur time.Duration) {
 	// Fetch the timings for the batch
 	var (
 		now     = mclock.Now()
@@ -61,6 +65,8 @@ func (st *insertStats) report(chain []*types.Block, index int, dirty common.Stor
 			"elapsed", common.PrettyDuration(elapsed), "mgasps", float64(st.usedGas) * 1000 / float64(elapsed),
 			"execTime", common.PrettyDuration(execTime), "execPercent", float64(execTime) / float64(elapsed),
 			"steps", steps,
+			"varDeclDur", common.PrettyDuration(varDeclDuration), "valDeclDurPercent", float64(varDeclDuration) / float64(elapsed),
+			"processPrepareDur", common.PrettyDuration(processPrepareDur), "processPrepareDurPercent", float64(processPrepareDur) / float64(elapsed),
 			"processDur", common.PrettyDuration(processDur), "processDurPercent", float64(processDur) / float64(elapsed),
 			"validateDur", common.PrettyDuration(validateDur), "validateDurPercent", float64(validateDur) / float64(elapsed),
 			"metricUpdate1", common.PrettyDuration(metricUpdateTime1), "metricUpdate1Percent", float64(metricUpdateTime1) / float64(elapsed),

core/vm/evm.go

@@ -291,7 +291,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas
 			ret, err = evm.interpreter.Run(contract, input, false)
 
 			interpreterRunTime := time.Since(getCodeBegin) - getCodeTime
-			log.Info("Inside Interpreter (gasps)", "getCodeDuration", common.PrettyDuration(getCodeTime), "RunDuration", common.PrettyDuration(interpreterRunTime), "cacheHit", hit)
+			log.Info("Inside Interpreter (gasps)", "depth", evm.depth, "getCodeDuration", common.PrettyDuration(getCodeTime), "RunDuration", common.PrettyDuration(interpreterRunTime), "cacheHit", hit)
 
 			gas = contract.Gas
 		}

core/vm/instructions.go

@@ -18,7 +18,9 @@ package vm
 
 import (
 	"github.com/ethereum/go-ethereum/core/vm/compiler"
+	"github.com/ethereum/go-ethereum/log"
 	"sync/atomic"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
@@ -374,7 +376,10 @@ func opCodeCopy(pc *uint64, interpreter *EVMInterpreter, scope *ScopeContext) ([
 	if interpreter.evm.Config.EnableOpcodeOptimizations && scope.Contract.optimized {
 		if scope.Contract.RawCode == nil || len(scope.Contract.RawCode) == 0 {
 			// if we have optimization, get rawCode from DB.
+			getCodeBegin := time.Now()
 			scope.Contract.RawCode = interpreter.evm.StateDB.GetCode(*scope.Contract.CodeAddr)
+			getCodeDur := time.Since(getCodeBegin)
+			log.Warn("opCodeCopy getRawCode (gasps)", "Duration", common.PrettyDuration(getCodeDur))
 		}
 		contractRawCode = scope.Contract.RawCode
 	}