Merge pull request #5657 from ethereum-optimism/aj/l1-fetch-timings

op-node: Add metrics recording the time spent waiting for L1 requests

op-node/metrics/metrics.go

@@ -103,6 +103,8 @@ type Metrics struct {
 	SequencerInconsistentL1Origin *EventMetrics
 	SequencerResets               *EventMetrics
 
+	L1RequestDurationSeconds *prometheus.HistogramVec
+
 	SequencerBuildingDiffDurationSeconds prometheus.Histogram
 	SequencerBuildingDiffTotal           prometheus.Counter
 
@@ -378,6 +380,14 @@ func NewMetrics(procName string) *Metrics {
 			Help:      "number of unverified execution payloads buffered in quarantine",
 		}),
 
+		L1RequestDurationSeconds: factory.NewHistogramVec(prometheus.HistogramOpts{
+			Namespace: ns,
+			Name:      "l1_request_seconds",
+			Buckets: []float64{
+				.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10},
+			Help: "Histogram of L1 request time",
+		}, []string{"request"}),
+
 		SequencerBuildingDiffDurationSeconds: factory.NewHistogram(prometheus.HistogramOpts{
 			Namespace: ns,
 			Name:      "sequencer_building_diff_seconds",
@@ -589,6 +599,11 @@ func (m *Metrics) RecordBandwidth(ctx context.Context, bwc *libp2pmetrics.Bandwi
 	}
 }
 
+// RecordL1RequestTime tracks the amount of time the derivation pipeline spent waiting for L1 data requests.
+func (m *Metrics) RecordL1RequestTime(method string, duration time.Duration) {
+	m.L1RequestDurationSeconds.WithLabelValues(method).Observe(float64(duration) / float64(time.Second))
+}
+
 // RecordSequencerBuildingDiffTime tracks the amount of time the sequencer was allowed between
 // start to finish, incl. sealing, minus the block time.
 // Ideally this is 0, realistically the sequencer scheduler may be busy with other jobs like syncing sometimes.

op-node/rollup/driver/driver.go

@@ -30,6 +30,7 @@ type Metrics interface {
 	RecordL1ReorgDepth(d uint64)
 
 	EngineMetrics
+	L1FetcherMetrics
 	SequencerMetrics
 }
 
@@ -103,6 +104,7 @@ type AltSync interface {
 
 // NewDriver composes an events handler that tracks L1 state, triggers L2 derivation, and optionally sequences new L2 blocks.
 func NewDriver(driverCfg *Config, cfg *rollup.Config, l2 L2Chain, l1 L1Chain, altSync AltSync, network Network, log log.Logger, snapshotLog log.Logger, metrics Metrics) *Driver {
+	l1 = NewMeteredL1Fetcher(l1, metrics)
 	l1State := NewL1State(log, metrics)
 	sequencerConfDepth := NewConfDepth(driverCfg.SequencerConfDepth, l1State.L1Head, l1)
 	findL1Origin := NewL1OriginSelector(log, cfg, sequencerConfDepth)

op-node/rollup/driver/metered_l1fetcher.go

+package driver
+
+import (
+	"context"
+	"time"
+
+	"github.com/ethereum-optimism/optimism/op-node/eth"
+	"github.com/ethereum-optimism/optimism/op-node/rollup/derive"
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core/types"
+)
+
+type L1FetcherMetrics interface {
+	RecordL1RequestTime(method string, duration time.Duration)
+}
+
+type MeteredL1Fetcher struct {
+	inner   derive.L1Fetcher
+	metrics L1FetcherMetrics
+	now     func() time.Time
+}
+
+func NewMeteredL1Fetcher(inner derive.L1Fetcher, metrics L1FetcherMetrics) *MeteredL1Fetcher {
+	return &MeteredL1Fetcher{
+		inner:   inner,
+		metrics: metrics,
+		now:     time.Now,
+	}
+}
+func (m *MeteredL1Fetcher) L1BlockRefByLabel(ctx context.Context, label eth.BlockLabel) (eth.L1BlockRef, error) {
+	defer m.recordTime("L1BlockRefByLabel")()
+	return m.inner.L1BlockRefByLabel(ctx, label)
+}
+
+func (m *MeteredL1Fetcher) L1BlockRefByNumber(ctx context.Context, num uint64) (eth.L1BlockRef, error) {
+	defer m.recordTime("L1BlockRefByNumber")()
+	return m.inner.L1BlockRefByNumber(ctx, num)
+}
+
+func (m *MeteredL1Fetcher) L1BlockRefByHash(ctx context.Context, hash common.Hash) (eth.L1BlockRef, error) {
+	defer m.recordTime("L1BlockRefByHash")()
+	return m.inner.L1BlockRefByHash(ctx, hash)
+}
+
+func (m *MeteredL1Fetcher) InfoByHash(ctx context.Context, hash common.Hash) (eth.BlockInfo, error) {
+	defer m.recordTime("InfoByHash")()
+	return m.inner.InfoByHash(ctx, hash)
+}
+
+func (m *MeteredL1Fetcher) InfoAndTxsByHash(ctx context.Context, hash common.Hash) (eth.BlockInfo, types.Transactions, error) {
+	defer m.recordTime("InfoAndTxsByHash")()
+	return m.inner.InfoAndTxsByHash(ctx, hash)
+}
+
+func (m *MeteredL1Fetcher) FetchReceipts(ctx context.Context, blockHash common.Hash) (eth.BlockInfo, types.Receipts, error) {
+	defer m.recordTime("FetchReceipts")()
+	return m.inner.FetchReceipts(ctx, blockHash)
+}
+
+var _ derive.L1Fetcher = (*MeteredL1Fetcher)(nil)
+
+func (m *MeteredL1Fetcher) recordTime(method string) func() {
+	start := m.now()
+	return func() {
+		end := m.now()
+		m.metrics.RecordL1RequestTime(method, end.Sub(start))
+	}
+}

op-node/rollup/driver/metered_l1fetcher_test.go

+package driver
+
+import (
+	"context"
+	"errors"
+	"testing"
+	"time"
+
+	"github.com/ethereum-optimism/optimism/op-node/eth"
+	"github.com/ethereum-optimism/optimism/op-node/testutils"
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core/types"
+	"github.com/stretchr/testify/mock"
+	"github.com/stretchr/testify/require"
+)
+
+func TestDurationRecorded(t *testing.T) {
+	num := uint64(1234)
+	hash := common.Hash{0xaa}
+	ref := eth.L1BlockRef{Number: num}
+	info := &testutils.MockBlockInfo{}
+	expectedErr := errors.New("test error")
+
+	tests := []struct {
+		method string
+		expect func(inner *testutils.MockL1Source)
+		call   func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source)
+	}{
+		{
+			method: "L1BlockRefByLabel",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				inner.ExpectL1BlockRefByLabel(eth.Finalized, ref, expectedErr)
+
+				result, err := fetcher.L1BlockRefByLabel(context.Background(), eth.Finalized)
+				require.Equal(t, ref, result)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+		{
+			method: "L1BlockRefByNumber",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				inner.ExpectL1BlockRefByNumber(num, ref, expectedErr)
+
+				result, err := fetcher.L1BlockRefByNumber(context.Background(), num)
+				require.Equal(t, ref, result)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+		{
+			method: "L1BlockRefByHash",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				inner.ExpectL1BlockRefByHash(hash, ref, expectedErr)
+
+				result, err := fetcher.L1BlockRefByHash(context.Background(), hash)
+				require.Equal(t, ref, result)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+		{
+			method: "InfoByHash",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				inner.ExpectInfoByHash(hash, info, expectedErr)
+
+				result, err := fetcher.InfoByHash(context.Background(), hash)
+				require.Equal(t, info, result)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+		{
+			method: "InfoAndTxsByHash",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				txs := types.Transactions{
+					&types.Transaction{},
+				}
+				inner.ExpectInfoAndTxsByHash(hash, info, txs, expectedErr)
+
+				actualInfo, actualTxs, err := fetcher.InfoAndTxsByHash(context.Background(), hash)
+				require.Equal(t, info, actualInfo)
+				require.Equal(t, txs, actualTxs)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+		{
+			method: "FetchReceipts",
+			call: func(t *testing.T, fetcher *MeteredL1Fetcher, inner *testutils.MockL1Source) {
+				rcpts := types.Receipts{
+					&types.Receipt{},
+				}
+				inner.ExpectFetchReceipts(hash, info, rcpts, expectedErr)
+
+				actualInfo, actualRcpts, err := fetcher.FetchReceipts(context.Background(), hash)
+				require.Equal(t, info, actualInfo)
+				require.Equal(t, rcpts, actualRcpts)
+				require.Equal(t, expectedErr, err)
+			},
+		},
+	}
+	for _, test := range tests {
+		test := test
+		t.Run(test.method, func(t *testing.T) {
+			duration := 200 * time.Millisecond
+			fetcher, inner, metrics := createFetcher(duration)
+			defer inner.AssertExpectations(t)
+			defer metrics.AssertExpectations(t)
+
+			metrics.ExpectRecordRequestTime(test.method, duration)
+
+			test.call(t, fetcher, inner)
+		})
+	}
+}
+
+// createFetcher creates a MeteredL1Fetcher with a mock inner.
+// The clock used to calculate the current time will advance by clockIncrement on each call, making it appear as if
+// each request takes that amount of time to execute.
+func createFetcher(clockIncrement time.Duration) (*MeteredL1Fetcher, *testutils.MockL1Source, *mockMetrics) {
+	inner := &testutils.MockL1Source{}
+	currTime := time.UnixMilli(1294812934000000)
+	clock := func() time.Time {
+		currTime = currTime.Add(clockIncrement)
+		return currTime
+	}
+	metrics := &mockMetrics{}
+	fetcher := MeteredL1Fetcher{
+		inner:   inner,
+		metrics: metrics,
+		now:     clock,
+	}
+	return &fetcher, inner, metrics
+}
+
+type mockMetrics struct {
+	mock.Mock
+}
+
+func (m *mockMetrics) RecordL1RequestTime(method string, duration time.Duration) {
+	m.MethodCalled("RecordL1RequestTime", method, duration)
+}
+
+func (m *mockMetrics) ExpectRecordRequestTime(method string, duration time.Duration) {
+	m.On("RecordL1RequestTime", method, duration).Once()
+}