Add block log

sequencer/batch.go

@@ -157,6 +157,7 @@ func (f *finalizer) finalizeWIPBatch(ctx context.Context, closeReason state.Clos
 
 	// Close the wip L2 block if it has transactions, otherwise we keep the wip L2 block to store it in the new wip batch
 	if !f.wipL2Block.isEmpty() {
+		f.setWIPL2BlockCloseReason(getReasonFromBatch(closeReason))
 		f.closeWIPL2Block(ctx)
 	}
 
@@ -180,6 +181,7 @@ func (f *finalizer) closeAndOpenNewWIPBatch(ctx context.Context, closeReason sta
 	// If we will process forced batches after we close the wip batch then we must close the current wip L2 block,
 	// since the processForcedBatches function needs to create new L2 blocks (cannot "reuse" the current wip L2 block if it's empty)
 	if processForcedBatches {
+		f.setWIPL2BlockCloseReason(getReasonFromBatch(closeReason))
 		f.closeWIPL2Block(ctx)
 	}
 

sequencer/l2block.go

@@ -239,6 +239,7 @@ func (f *finalizer) processL2Block(ctx context.Context, l2Block *L2Block) error
 			blockResponse.BlockNumber, l2Block.trackingNum, l2Block.metrics.log(), f.metrics.startsAt().Unix(), f.metrics.log())
 	}
 
+	log.Infof("%v", l2Block.metrics.Summary(blockResponse.BlockNumber, f.wipBatch.batchNumber, l2Block.timestamp))
 	return nil
 }
 
@@ -448,6 +449,7 @@ func (f *finalizer) finalizeWIPL2Block(ctx context.Context) {
 	prevTimestamp := f.wipL2Block.timestamp
 	prevL1InfoTreeIndex := f.wipL2Block.l1InfoTreeExitRoot.L1InfoTreeIndex
 
+	f.setWIPL2BlockCloseReason(BlockMaxDeltaTimestamp)
 	f.closeWIPL2Block(ctx)
 
 	f.openNewWIPL2Block(ctx, prevTimestamp, &prevL1InfoTreeIndex)

sequencer/l2block_xlayer.go

@@ -0,0 +1,7 @@
+package sequencer
+
+func (f *finalizer) setWIPL2BlockCloseReason(closeReason BlockClosingReason) {
+	if f.wipL2Block != nil {
+		f.wipL2Block.metrics.closeReason = string(closeReason)
+	}
+}

sequencer/metrics.go

@@ -44,6 +44,8 @@ type metrics struct {
 	gas                uint64
 	estimatedTxsPerSec float64
 	estimatedGasPerSec uint64
+
+	closeReason string
 }
 
 func (m *metrics) sub(mSub metrics) {

sequencer/metrics_xlayer.go

@@ -0,0 +1,45 @@
+package sequencer
+
+import (
+	"fmt"
+
+	"github.com/0xPolygonHermez/zkevm-node/state"
+)
+
+// BlockClosingReason is the reason why a block is closed.
+type BlockClosingReason string
+
+const (
+	// BlockMaxDeltaTimestamp is the closing reason when the max delta timestamp is reached.
+	BlockMaxDeltaTimestamp BlockClosingReason = "Max delta timestamp"
+)
+
+func getReasonFromBatch(batchCloseReason state.ClosingReason) BlockClosingReason {
+	return BlockClosingReason(fmt.Sprintf("Batch closed, %v", batchCloseReason))
+}
+
+// Summary returns the metrics summary.
+func (m *metrics) Summary(blockNum, batchNum, timestamp uint64) string {
+	TotalSequencerTime := "SequencerTime<" + fmt.Sprintf("%v", m.sequencerTime().Milliseconds()) +
+		"ms, newL2Block<" + fmt.Sprintf("%v", m.newL2BlockTimes.sequencer.Milliseconds()) +
+		"ms>, txs<" + fmt.Sprintf("%v", m.transactionsTimes.sequencer.Milliseconds()) +
+		"ms>, l2Block<" + fmt.Sprintf("%v", m.l2BlockTimes.sequencer.Milliseconds()) + "ms>>, "
+
+	TotalExecutorTime := "ExecutorTime<" + fmt.Sprintf("%v", m.executorTime().Milliseconds()) +
+		"ms, newL2Block<" + fmt.Sprintf("%v", m.newL2BlockTimes.executor.Milliseconds()) +
+		"ms>, txs<" + fmt.Sprintf("%v", m.transactionsTimes.executor.Milliseconds()) +
+		"ms>, l2Block<" + fmt.Sprintf("%v", m.l2BlockTimes.executor.Milliseconds()) + "ms>>, "
+
+	result := "BlockNumber<" + fmt.Sprintf("%v", blockNum) + ">, " +
+		"BatchNum<" + fmt.Sprintf("%v", batchNum) + ">, " +
+		"TxCount<" + fmt.Sprintf("%v", m.l2BlockTxsCount) + ">, " +
+		"Gas<" + fmt.Sprintf("%v", m.gas) + ">, " +
+		"TotalTime<" + fmt.Sprintf("%v", m.totalTime().Milliseconds()) + "ms>, " +
+		"IdleTime<" + fmt.Sprintf("%v", m.idleTime.Milliseconds()) + "ms>, " +
+		TotalSequencerTime +
+		TotalExecutorTime +
+		"CloseReason<" + m.closeReason + ">, " +
+		"Timestamp<" + fmt.Sprintf("%v", timestamp) + ">, "
+
+	return result
+}

sequencer/metrics_xlayer_test.go

@@ -0,0 +1,32 @@
+package sequencer
+
+import (
+	"testing"
+	"time"
+)
+
+func Test_Summary(t *testing.T) {
+	tests := []struct {
+		name    string
+		metrics *metrics
+	}{
+		{"1", &metrics{
+			closedAt:           time.Now(),
+			processedTxsCount:  10,
+			l2BlockTxsCount:    10,
+			idleTime:           time.Second,
+			newL2BlockTimes:    processTimes{sequencer: time.Second, executor: time.Second},
+			transactionsTimes:  processTimes{sequencer: time.Second, executor: time.Second},
+			l2BlockTimes:       processTimes{sequencer: time.Second, executor: time.Second},
+			gas:                10,
+			estimatedTxsPerSec: 10,
+			estimatedGasPerSec: 10,
+			closeReason:        "deadline",
+		}},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			t.Log(tt.metrics.Summary(1, 3, uint64(time.Now().Unix())))
+		})
+	}
+}