feat(metrics): add debug.timers flag and some metrics (#786)

cmd/rpcdaemon/commands/send_transaction.go

@@ -18,10 +18,14 @@ import (
 	"github.com/ledgerwatch/erigon/eth/ethconfig"
 	"github.com/ledgerwatch/erigon/params"
 	"github.com/ledgerwatch/erigon/rlp"
+	"github.com/ledgerwatch/erigon/zk/utils"
 )
 
 // SendRawTransaction implements eth_sendRawTransaction. Creates new message call transaction or a contract creation for previously-signed transactions.
 func (api *APIImpl) SendRawTransaction(ctx context.Context, encodedTx hexutility.Bytes) (common.Hash, error) {
+	t := utils.StartTimer("rpc", "sendrawtransaction")
+	defer t.LogTimer()
+
 	tx, err := api.db.BeginRo(ctx)
 	if err != nil {
 		return common.Hash{}, err

cmd/utils/flags.go

@@ -606,6 +606,11 @@ var (
 		Usage: "The URL of the data availability service",
 		Value: "",
 	}
+	DebugTimers = cli.BoolFlag{
+		Name:  "debug.timers",
+		Usage: "Enable debug timers",
+		Value: false,
+	}
 	DebugNoSync = cli.BoolFlag{
 		Name:  "debug.no-sync",
 		Usage: "Disable syncing",

eth/ethconfig/config_zkevm.go

@@ -57,6 +57,7 @@ type Zk struct {
 	SyncLimit             uint64
 	Gasless               bool
 
+	DebugTimers    bool
 	DebugNoSync    bool
 	DebugLimit     uint64
 	DebugStep      uint64

turbo/cli/default_flags.go

@@ -212,6 +212,7 @@ var DefaultFlags = []cli.Flag{
 	&utils.SyncLimit,
 	&utils.SupportGasless,
 	&utils.ExecutorPayloadOutput,
+	&utils.DebugTimers,
 	&utils.DebugNoSync,
 	&utils.DebugLimit,
 	&utils.DebugStep,

turbo/cli/flags_zkevm.go

@@ -13,6 +13,7 @@ import (
 	"github.com/ledgerwatch/erigon/eth/ethconfig"
 	"github.com/ledgerwatch/erigon/zk/sequencer"
 	"github.com/urfave/cli/v2"
+	utils2 "github.com/ledgerwatch/erigon/zk/utils"
 )
 
 func ApplyFlagsForZkConfig(ctx *cli.Context, cfg *ethconfig.Config) {
@@ -144,6 +145,7 @@ func ApplyFlagsForZkConfig(ctx *cli.Context, cfg *ethconfig.Config) {
 		WitnessFull:                            ctx.Bool(utils.WitnessFullFlag.Name),
 		SyncLimit:                              ctx.Uint64(utils.SyncLimit.Name),
 		Gasless:                                ctx.Bool(utils.SupportGasless.Name),
+		DebugTimers:                            ctx.Bool(utils.DebugTimers.Name),
 		DebugNoSync:                            ctx.Bool(utils.DebugNoSync.Name),
 		DebugLimit:                             ctx.Uint64(utils.DebugLimit.Name),
 		DebugStep:                              ctx.Uint64(utils.DebugStep.Name),
@@ -156,6 +158,8 @@ func ApplyFlagsForZkConfig(ctx *cli.Context, cfg *ethconfig.Config) {
 		DataStreamPort:                         ctx.Uint(utils.DataStreamPort.Name),
 	}
 
+	utils2.EnableTimer(cfg.DebugTimers)
+
 	checkFlag(utils.L2ChainIdFlag.Name, cfg.L2ChainId)
 	if !sequencer.IsSequencer() {
 		checkFlag(utils.L2RpcUrlFlag.Name, cfg.L2RpcUrl)

zk/datastream/server/datastream_populate.go

@@ -22,6 +22,9 @@ func (srv *DataStreamServer) WriteBlocksToStream(
 	from, to uint64,
 	logPrefix string,
 ) error {
+	t := utils.StartTimer("write-stream", "writeblockstostream")
+	defer t.LogTimer()
+
 	var err error
 
 	logTicker := time.NewTicker(10 * time.Second)
@@ -93,6 +96,9 @@ func (srv *DataStreamServer) WriteBlockToStream(
 	batchNum, prevBatchNum,
 	blockNum uint64,
 ) error {
+	t := utils.StartTimer("write-stream", "writeblockstostream")
+	defer t.LogTimer()
+
 	var err error
 
 	if err = srv.UnwindIfNecessary(logPrefix, reader, blockNum, prevBatchNum, batchNum); err != nil {

zk/utils/debug_timer.go

@@ -0,0 +1,44 @@
+package utils
+
+import (
+	"fmt"
+	"time"
+
+	"github.com/ledgerwatch/log/v3"
+)
+
+var timerEnabled bool
+
+type Timer struct {
+	start     time.Time
+	taskNames []string
+}
+
+func EnableTimer(enable bool) {
+	timerEnabled = enable
+}
+
+func StartTimer(taskNames ...string) *Timer {
+	if !timerEnabled {
+		return nil
+	}
+	return &Timer{
+		start:     time.Now(),
+		taskNames: taskNames,
+	}
+}
+
+func (t *Timer) LogTimer() {
+	if !timerEnabled || t == nil {
+		return
+	}
+
+	elapsed := time.Since(t.start)
+	logArgs := []interface{}{"duration", elapsed, "task", t.taskNames[0]}
+
+	for i, task := range t.taskNames[1:] {
+		logArgs = append(logArgs, fmt.Sprintf("subtask%d", i+1), task)
+	}
+
+	log.Info("[cdk-metric]", logArgs...)
+}

zk/witness/witness.go

@@ -69,6 +69,9 @@ func NewGenerator(
 }
 
 func (g *Generator) GetWitnessByBatch(tx kv.Tx, ctx context.Context, batchNum uint64, debug, witnessFull bool) ([]byte, error) {
+	t := zkUtils.StartTimer("witness", "getwitnessbybatch")
+	defer t.LogTimer()
+
 	reader := hermez_db.NewHermezDbReader(tx)
 	badBatch, err := reader.GetInvalidBatch(batchNum)
 	if err != nil {
@@ -143,6 +146,9 @@ func (g *Generator) GetWitnessByBatch(tx kv.Tx, ctx context.Context, batchNum ui
 }
 
 func (g *Generator) GetWitnessByBlockRange(tx kv.Tx, ctx context.Context, startBlock, endBlock uint64, debug, witnessFull bool) ([]byte, error) {
+	t := zkUtils.StartTimer("witness", "getwitnessbyblockrange")
+	defer t.LogTimer()
+
 	if startBlock > endBlock {
 		return nil, ErrEndBeforeStart
 	}
@@ -165,6 +171,9 @@ func (g *Generator) GetWitnessByBlockRange(tx kv.Tx, ctx context.Context, startB
 }
 
 func (g *Generator) generateWitness(tx kv.Tx, ctx context.Context, blocks []*eritypes.Block, debug, witnessFull bool) ([]byte, error) {
+	t := zkUtils.StartTimer("witness", "generatewitness")
+	defer t.LogTimer()
+
 	endBlock := blocks[len(blocks)-1].NumberU64()
 	startBlock := blocks[0].NumberU64()