[WIP] debug trace profile

evmrpc/block_trace_profiled.go

@@ -136,7 +136,7 @@ func (api *DebugAPI) profiledTraceBlockSequential(
 			TxIndex:     i,
 			TxHash:      tx.Hash(),
 		}
-		res, err := api.profiledTraceTx(ctx, tx, msg, txctx, blockCtx, statedb, config, nil, false)
+		res, err := api.profiledTraceTx(ctx, tx, msg, txctx, blockCtx, statedb, config, nil, false, nil)
 		if err != nil {
 			results[i] = &tracers.TxTraceResult{TxHash: tx.Hash(), Error: err.Error()}
 		} else {
@@ -202,7 +202,7 @@ func (api *DebugAPI) profiledTraceBlockParallel(
 					results[task.index] = &tracers.TxTraceResult{TxHash: tx.Hash(), Error: err.Error()}
 					continue
 				}
-				res, err := api.profiledTraceTx(ctx, tx, msg, txctx, blockCtx, task.statedb, config, nil, true)
+				res, err := api.profiledTraceTx(ctx, tx, msg, txctx, blockCtx, task.statedb, config, nil, true, nil)
 				if err != nil {
 					results[task.index] = &tracers.TxTraceResult{TxHash: tx.Hash(), Error: err.Error()}
 				} else {
@@ -315,6 +315,7 @@ func (api *DebugAPI) profiledTraceTx(
 	config *tracers.TraceConfig,
 	precompiles vm.PrecompiledContracts,
 	noFlush bool,
+	phaseDurations *traceExecutionPhaseDurations,
 ) (value interface{}, returnErr error) {
 	var (
 		tracer    *tracers.Tracer
@@ -379,21 +380,33 @@ func (api *DebugAPI) profiledTraceTx(
 
 	statedb.SetTxContext(txctx.TxHash, txctx.TxIndex)
 	var prepareTxErr error
+	prepareStart := time.Now()
 	if noFlush {
 		prepareTxErr = api.backend.PrepareTxNoFlush(statedb, tx)
 	} else {
 		prepareTxErr = api.backend.PrepareTx(statedb, tx)
 	}
+	if phaseDurations != nil {
+		phaseDurations.PrepareTxNanos = time.Since(prepareStart).Nanoseconds()
+	}
 	if prepareTxErr != nil {
 		return profiledErrorTrace(prepareTxErr, tx, message, txctx, vmctx, config)
 	}
+	executionStart := time.Now()
 	_, err = core.ApplyTransactionWithEVM(message, new(core.GasPool).AddGas(message.GasLimit), statedb, vmctx.BlockNumber, txctx.BlockHash, tx, &usedGas, evm)
+	if phaseDurations != nil {
+		phaseDurations.ExecutionNanos = time.Since(executionStart).Nanoseconds()
+	}
 	if err != nil {
 		return profiledErrorTrace(err, tx, message, txctx, vmctx, config)
 	}
+	resultStart := time.Now()
 	tracerMtx.Lock()
 	res, err := tracer.GetResult()
 	tracerMtx.Unlock()
+	if phaseDurations != nil {
+		phaseDurations.TraceResultNanos = time.Since(resultStart).Nanoseconds()
+	}
 	if err == nil && errors.Is(deadlineCtx.Err(), context.DeadlineExceeded) {
 		err = errors.New("execution timeout")
 	}

evmrpc/tests/tracers_test.go

@@ -156,6 +156,61 @@ func TestTraceStateAccess(t *testing.T) {
 	)
 }
 
+func TestTraceTransactionProfile(t *testing.T) {
+	cwIter := "sei18cszlvm6pze0x9sz32qnjq4vtd45xehqs8dq7cwy8yhq35wfnn3quh5sau" // hardcoded
+	txData := callWasmIter(0, cwIter)
+	signedTx := signTxWithMnemonic(txData, mnemonic1)
+	txBz := encodeEvmTx(txData, signedTx)
+
+	SetupTestServer(t, [][][]byte{{txBz}}, mnemonicInitializer(mnemonic1), cwIterInitializer(mnemonic1)).Run(
+		func(port int) {
+			res := sendRequestWithNamespace("debug", port, "traceTransactionProfile", signedTx.Hash().Hex(), map[string]interface{}{
+				"timeout": "60s",
+			})
+			result := res["result"].(map[string]interface{})
+			require.Contains(t, result, "trace")
+
+			profile := result["profile"].(map[string]interface{})
+			require.Greater(t, profile["totalNanos"].(float64), float64(0))
+			require.Greater(t, profile["historicalDbLookupNanos"].(float64), float64(0))
+
+			store := profile["store"].(map[string]interface{})
+			modules := store["modules"].(map[string]interface{})
+			foundIteratorTrace := false
+			foundLowLevelPebbleTrace := false
+			foundLowLevelGetPathTrace := false
+			for _, module := range modules {
+				moduleMap := module.(map[string]interface{})
+				iterators, ok := moduleMap["iterators"].([]interface{})
+				if ok && len(iterators) > 0 {
+					foundIteratorTrace = true
+				}
+				lowLevelStats, ok := moduleMap["lowLevelStats"].(map[string]interface{})
+				if ok {
+					if _, ok := lowLevelStats["pebble.last"]; ok {
+						foundLowLevelPebbleTrace = true
+					}
+					if _, ok := lowLevelStats["pebble.seekLT"]; ok {
+						foundLowLevelPebbleTrace = true
+					}
+					if _, ok := lowLevelStats["mvcc.getMVCCSlice"]; ok {
+						foundLowLevelGetPathTrace = true
+					}
+					if _, ok := lowLevelStats["pebble.iterValue"]; ok {
+						foundLowLevelGetPathTrace = true
+					}
+					if _, ok := lowLevelStats["mvcc.decodeKeyVersion"]; ok {
+						foundLowLevelGetPathTrace = true
+					}
+				}
+			}
+			require.True(t, foundIteratorTrace, "expected at least one iterator sample in the store trace")
+			require.True(t, foundLowLevelPebbleTrace, "expected low-level pebble iterator timings in the store trace")
+			require.True(t, foundLowLevelGetPathTrace, "expected low-level getMVCCSlice timings in the store trace")
+		},
+	)
+}
+
 func TestTraceBlockWithFailureThenSuccess(t *testing.T) {
 	maxUseiInWei := sdk.NewInt(math.MaxInt64).Mul(state.SdkUseiToSweiMultiplier).BigInt()
 	insufficientFundsTx := signAndEncodeTx(sendAmount(0, maxUseiInWei), mnemonic1)

evmrpc/trace_profile.go

@@ -0,0 +1,159 @@
+package evmrpc
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"time"
+
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core"
+	gethtypes "github.com/ethereum/go-ethereum/core/types"
+	"github.com/ethereum/go-ethereum/core/vm"
+	"github.com/ethereum/go-ethereum/eth/tracers"
+	sdk "github.com/sei-protocol/sei-chain/sei-cosmos/types"
+	"github.com/sei-protocol/sei-chain/x/evm/state"
+)
+
+type traceExecutionPhaseDurations struct {
+	PrepareTxNanos   int64 `json:"prepareTxNanos"`
+	ExecutionNanos   int64 `json:"executionNanos"`
+	TraceResultNanos int64 `json:"traceResultNanos"`
+}
+
+type TraceTransactionProfilePhases struct {
+	LookupTransactionNanos   int64 `json:"lookupTransactionNanos"`
+	LoadBlockNanos           int64 `json:"loadBlockNanos"`
+	ReplayHistoricalTxsNanos int64 `json:"replayHistoricalTxsNanos"`
+	BuildBlockContextNanos   int64 `json:"buildBlockContextNanos"`
+	traceExecutionPhaseDurations
+}
+
+type TraceTransactionProfile struct {
+	TotalNanos              int64                         `json:"totalNanos"`
+	HistoricalDBLookupNanos int64                         `json:"historicalDbLookupNanos"`
+	OtherNanos              int64                         `json:"otherNanos"`
+	Phases                  TraceTransactionProfilePhases `json:"phases"`
+	Store                   *sdk.StoreTraceDump           `json:"store,omitempty"`
+}
+
+type TraceTransactionProfileResponse struct {
+	Trace   interface{}             `json:"trace"`
+	Profile TraceTransactionProfile `json:"profile"`
+}
+
+func (api *DebugAPI) TraceTransactionProfile(ctx context.Context, hash common.Hash, config *tracers.TraceConfig) (result interface{}, returnErr error) {
+	startTime := time.Now()
+	defer recordMetricsWithError("debug_traceTransactionProfile", api.connectionType, startTime, returnErr)
+
+	ctx, done, err := api.prepareTraceContext(ctx)
+	if err != nil {
+		return nil, err
+	}
+	defer done()
+
+	profileStart := time.Now()
+	tracingBackend := api.newProfileTracingBackend()
+	var phases TraceTransactionProfilePhases
+
+	lookupStart := time.Now()
+	found, tx, blockHash, _, index, err := tracingBackend.GetTransaction(ctx, hash)
+	phases.LookupTransactionNanos = time.Since(lookupStart).Nanoseconds()
+	if err != nil {
+		return nil, err
+	}
+	if !found || tx == nil {
+		return nil, errors.New("transaction not found")
+	}
+
+	loadBlockStart := time.Now()
+	block, _, err := tracingBackend.BlockByHash(ctx, blockHash)
+	phases.LoadBlockNanos = time.Since(loadBlockStart).Nanoseconds()
+	if err != nil {
+		return nil, err
+	}
+	if block == nil {
+		return nil, fmt.Errorf("block %s not found", blockHash.Hex())
+	}
+	if block.NumberU64() == 0 {
+		return nil, errors.New("genesis is not traceable")
+	}
+
+	replayStart := time.Now()
+	statedb, _, err := tracingBackend.ReplayTransactionTillIndex(ctx, block, int(index)-1) //nolint:gosec
+	phases.ReplayHistoricalTxsNanos = time.Since(replayStart).Nanoseconds()
+	if err != nil {
+		return nil, err
+	}
+
+	blockContextStart := time.Now()
+	blockCtx, err := tracingBackend.GetBlockContext(ctx, block, statedb, tracingBackend)
+	phases.BuildBlockContextNanos = time.Since(blockContextStart).Nanoseconds()
+	if err != nil {
+		return nil, fmt.Errorf("cannot get block context: %w", err)
+	}
+
+	signer := gethtypes.MakeSigner(tracingBackend.ChainConfig(), block.Number(), block.Time())
+	msg, _ := core.TransactionToMessage(tx, signer, block.BaseFee())
+	txctx := &tracers.Context{
+		BlockHash:   blockHash,
+		BlockNumber: block.Number(),
+		TxIndex:     int(index), //nolint:gosec
+		TxHash:      tx.Hash(),
+	}
+
+	traceResult, err := api.profiledTraceTx(ctx, tx, msg, txctx, blockCtx, statedb, config, nil, false, &phases.traceExecutionPhaseDurations)
+	if err != nil {
+		return nil, err
+	}
+
+	storeDump := dumpStoreTrace(statedb)
+	historicalLookupNanos := historicalLookupNanos(storeDump)
+	totalNanos := time.Since(profileStart).Nanoseconds()
+	otherNanos := totalNanos - historicalLookupNanos - phases.ExecutionNanos
+	if otherNanos < 0 {
+		otherNanos = 0
+	}
+
+	return TraceTransactionProfileResponse{
+		Trace: traceResult,
+		Profile: TraceTransactionProfile{
+			TotalNanos:              totalNanos,
+			HistoricalDBLookupNanos: historicalLookupNanos,
+			OtherNanos:              otherNanos,
+			Phases:                  phases,
+			Store:                   storeDump,
+		},
+	}, nil
+}
+
+func (api *DebugAPI) newProfileTracingBackend() *Backend {
+	tracingBackend := *api.backend
+	tracingBackend.ctxProvider = func(height int64) sdk.Context {
+		return api.ctxProvider(height).WithIsTracing(true)
+	}
+	return &tracingBackend
+}
+
+func dumpStoreTrace(statedb vm.StateDB) *sdk.StoreTraceDump {
+	typedStateDB := state.GetDBImpl(statedb)
+	if typedStateDB == nil || typedStateDB.Ctx().StoreTracer() == nil {
+		return nil
+	}
+	if dumpable, ok := typedStateDB.Ctx().StoreTracer().(interface{ Dump() sdk.StoreTraceDump }); ok {
+		dump := dumpable.Dump()
+		return &dump
+	}
+	return nil
+}
+
+func historicalLookupNanos(storeDump *sdk.StoreTraceDump) int64 {
+	if storeDump == nil {
+		return 0
+	}
+	var total int64
+	for _, key := range []string{"get", "has", "iterator", "iteratorNext"} {
+		total += storeDump.Stats[key].TotalNanos
+	}
+	return total
+}

sei-cosmos/store/cachekv/store.go

@@ -10,6 +10,7 @@ import (
 	"github.com/sei-protocol/sei-chain/sei-cosmos/store/tracekv"
 	"github.com/sei-protocol/sei-chain/sei-cosmos/store/types"
 	"github.com/sei-protocol/sei-chain/sei-cosmos/types/kv"
+	seidbtypes "github.com/sei-protocol/sei-chain/sei-db/db_engine/types"
 	dbm "github.com/tendermint/tm-db"
 )
 
@@ -352,6 +353,14 @@ func (store *Store) GetParent() types.KVStore {
 	return store.parent
 }
 
+func (store *Store) SetReadTraceCollector(collector seidbtypes.ReadTraceCollector) {
+	if tracerAware, ok := store.parent.(interface {
+		SetReadTraceCollector(seidbtypes.ReadTraceCollector)
+	}); ok {
+		tracerAware.SetReadTraceCollector(collector)
+	}
+}
+
 func (store *Store) DeleteAll(start, end []byte) error {
 	for _, k := range store.GetAllKeyStrsInRange(start, end) {
 		store.Delete([]byte(k))