cannon: Add MTCannon VM metrics (#13133)

* cannon: Track steps between ll and sc

* cannon: Track rmw failures, keep counts for rmw ops

* cannon: Add unit tests for stats tracking

* cannon: Simplify step count stats

* cannon: Track explicit memory reservation invalidation

* cannon: Set stats on DebugInfo

* cannon: Rename method

* cannon: Track forced preemptions

* cannon: Track failed wakeup traversals

* cannon: Track idle steps for thread 0

* cannon: Reorganize vm metrics, add methods to record new stats

* cannon: Use uint64 over int

* cannon: Record new metrics

* cannon: Update readme run-trace flag

* cannon: Use uint64 type consistently

* cannon: Add debugInfo serialization test

* cannon: Check metrics in executor test

* cannon: Record total steps

* cannon: Check error in test

* cannon: Enable stats tracking via --debug-info flag

* cannon: Fix steps json field name

* cannon: Keep a small cache of ll steps for more accurate tracking

* cannon: Tweak test

* cannon: Modify test to better validate json parsing

* cannon: Use non-threadsafe simplelru

cannon/cmd/run.go

@@ -11,6 +11,12 @@ import (
 	"strings"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/pkg/profile"
+	"github.com/urfave/cli/v2"
+
 	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
 	"github.com/ethereum-optimism/optimism/cannon/mipsevm/arch"
 	mipsexec "github.com/ethereum-optimism/optimism/cannon/mipsevm/exec"
@@ -20,11 +26,6 @@ import (
 	"github.com/ethereum-optimism/optimism/op-service/ioutil"
 	"github.com/ethereum-optimism/optimism/op-service/jsonutil"
 	"github.com/ethereum-optimism/optimism/op-service/serialize"
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/common/hexutil"
-	"github.com/ethereum/go-ethereum/log"
-	"github.com/pkg/profile"
-	"github.com/urfave/cli/v2"
 )
 
 var (
@@ -379,6 +380,8 @@ func Run(ctx *cli.Context) error {
 	}
 	l.Info("Loaded input state", "version", state.Version)
 	vm := state.CreateVM(l, po, outLog, errLog, meta)
+
+	// Enable debug/stats tracking as requested
 	debugProgram := ctx.Bool(RunDebugFlag.Name)
 	if debugProgram {
 		if metaPath := ctx.Path(RunMetaFlag.Name); metaPath == "" {
@@ -388,6 +391,9 @@ func Run(ctx *cli.Context) error {
 			return fmt.Errorf("failed to initialize debug mode: %w", err)
 		}
 	}
+	if debugInfoFile := ctx.Path(RunDebugInfoFlag.Name); debugInfoFile != "" {
+		vm.EnableStats()
+	}
 
 	proofFmt := ctx.String(RunProofFmtFlag.Name)
 	snapshotFmt := ctx.String(RunSnapshotFmtFlag.Name)

cannon/mipsevm/debug.go

@@ -7,4 +7,13 @@ type DebugInfo struct {
 	MemoryUsed          hexutil.Uint64 `json:"memory_used"`
 	NumPreimageRequests int            `json:"num_preimage_requests"`
 	TotalPreimageSize   int            `json:"total_preimage_size"`
+	TotalSteps          uint64         `json:"total_steps"`
+	//  Multithreading-related stats below
+	RmwSuccessCount              uint64 `json:"rmw_success_count"`
+	RmwFailCount                 uint64 `json:"rmw_fail_count"`
+	MaxStepsBetweenLLAndSC       uint64 `json:"max_steps_between_ll_and_sc"`
+	ReservationInvalidationCount uint64 `json:"reservation_invalidation_count"`
+	ForcedPreemptionCount        uint64 `json:"forced_preemption_count"`
+	FailedWakeupCount            uint64 `json:"failed_wakeup_count"`
+	IdleStepCountThread0         uint64 `json:"idle_step_count_thread_0"`
 }

cannon/mipsevm/debug_test.go

+package mipsevm
+
+import (
+	"math"
+	"path/filepath"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/ethereum-optimism/optimism/op-service/ioutil"
+	"github.com/ethereum-optimism/optimism/op-service/jsonutil"
+)
+
+func TestDebugInfo_Serialization(t *testing.T) {
+	debugInfo := &DebugInfo{
+		Pages:                        1,
+		MemoryUsed:                   2,
+		NumPreimageRequests:          3,
+		TotalPreimageSize:            4,
+		TotalSteps:                   123456,
+		RmwSuccessCount:              5,
+		RmwFailCount:                 6,
+		MaxStepsBetweenLLAndSC:       7,
+		ReservationInvalidationCount: 8,
+		ForcedPreemptionCount:        9,
+		FailedWakeupCount:            10,
+		IdleStepCountThread0:         math.MaxUint64,
+	}
+
+	// Serialize to file
+	dir := t.TempDir()
+	path := filepath.Join(dir, "debug-info-test.txt")
+	err := jsonutil.WriteJSON(debugInfo, ioutil.ToAtomicFile(path, 0o644))
+	require.NoError(t, err)
+
+	// Deserialize
+	fromJson, err := jsonutil.LoadJSON[DebugInfo](path)
+	require.NoError(t, err)
+
+	require.Equal(t, debugInfo, fromJson)
+}

cannon/mipsevm/iface.go

@@ -90,6 +90,9 @@ type FPVM interface {
 	// InitDebug initializes the debug mode of the VM
 	InitDebug() error
 
+	// EnableStats if supported by the VM, enables some additional statistics that can be retrieved via GetDebugInfo()
+	EnableStats()
+
 	// LookupSymbol returns the symbol located at the specified address.
 	// May return an empty string if there's no symbol table available.
 	LookupSymbol(addr arch.Word) string

cannon/mipsevm/multithreaded/instrumented.go

@@ -20,6 +20,7 @@ type InstrumentedState struct {
 
 	memoryTracker *exec.MemoryTrackerImpl
 	stackTracker  ThreadedStackTracker
+	statsTracker  StatsTracker
 
 	preimageOracle *exec.TrackingPreimageOracleReader
 	meta           mipsevm.Metadata
@@ -35,6 +36,7 @@ func NewInstrumentedState(state *State, po mipsevm.PreimageOracle, stdOut, stdEr
 		stdErr:         stdErr,
 		memoryTracker:  exec.NewMemoryTracker(state.Memory),
 		stackTracker:   &NoopThreadedStackTracker{},
+		statsTracker:   NoopStatsTracker(),
 		preimageOracle: exec.NewTrackingPreimageOracleReader(po),
 		meta:           meta,
 	}
@@ -49,6 +51,10 @@ func (m *InstrumentedState) InitDebug() error {
 	return nil
 }
 
+func (m *InstrumentedState) EnableStats() {
+	m.statsTracker = NewStatsTracker()
+}
+
 func (m *InstrumentedState) Step(proof bool) (wit *mipsevm.StepWitness, err error) {
 	m.preimageOracle.Reset()
 	m.memoryTracker.Reset(proof)
@@ -100,12 +106,15 @@ func (m *InstrumentedState) GetState() mipsevm.FPVMState {
 }
 
 func (m *InstrumentedState) GetDebugInfo() *mipsevm.DebugInfo {
-	return &mipsevm.DebugInfo{
+	debugInfo := &mipsevm.DebugInfo{
 		Pages:               m.state.Memory.PageCount(),
 		MemoryUsed:          hexutil.Uint64(m.state.Memory.UsageRaw()),
 		NumPreimageRequests: m.preimageOracle.NumPreimageRequests(),
 		TotalPreimageSize:   m.preimageOracle.TotalPreimageSize(),
+		TotalSteps:          m.state.GetStep(),
 	}
+	m.statsTracker.populateDebugInfo(debugInfo)
+	return debugInfo
 }
 
 func (m *InstrumentedState) Traceback() {

cannon/mipsevm/multithreaded/mips.go

@@ -129,8 +129,7 @@ func (m *InstrumentedState) handleSyscall() error {
 				return nil
 			}
 		case exec.FutexWakePrivate:
-			// Trigger thread traversal starting from the left stack until we find one waiting on the wakeup
-			// address
+			// Trigger a wakeup traversal
 			m.state.Wakeup = effAddr
 			// Don't indicate to the program that we've woken up a waiting thread, as there are no guarantees.
 			// The woken up thread should indicate this in userspace.
@@ -139,6 +138,7 @@ func (m *InstrumentedState) handleSyscall() error {
 			exec.HandleSyscallUpdates(&thread.Cpu, &thread.Registers, v0, v1)
 			m.preemptThread(thread)
 			m.state.TraverseRight = len(m.state.LeftThreadStack) == 0
+			m.statsTracker.trackWakeupTraversalStart()
 			return nil
 		default:
 			v0 = exec.SysErrorSignal
@@ -289,6 +289,7 @@ func (m *InstrumentedState) doMipsStep() error {
 			if thread.FutexVal == mem {
 				// still got expected value, continue sleeping, try next thread.
 				m.preemptThread(thread)
+				m.statsTracker.trackWakeupFail()
 				return nil
 			} else {
 				// wake thread up, the value at its address changed!
@@ -309,6 +310,7 @@ func (m *InstrumentedState) doMipsStep() error {
 			}
 		}
 		m.preemptThread(thread)
+		m.statsTracker.trackForcedPreemption()
 		return nil
 	}
 	m.state.StepsSinceLastContextSwitch += 1
@@ -349,6 +351,7 @@ func (m *InstrumentedState) handleMemoryUpdate(effMemAddr Word) {
 	if effMemAddr == (arch.AddressMask & m.state.LLAddress) {
 		// Reserved address was modified, clear the reservation
 		m.clearLLMemoryReservation()
+		m.statsTracker.trackReservationInvalidation()
 	}
 }
 
@@ -384,6 +387,8 @@ func (m *InstrumentedState) handleRMWOps(insn, opcode uint32) error {
 		m.state.LLReservationStatus = targetStatus
 		m.state.LLAddress = addr
 		m.state.LLOwnerThread = threadId
+
+		m.statsTracker.trackLL(threadId, m.GetState().GetStep())
 	case exec.OpStoreConditional, exec.OpStoreConditional64:
 		if m.state.LLReservationStatus == targetStatus && m.state.LLOwnerThread == threadId && m.state.LLAddress == addr {
 			// Complete atomic update: set memory and return 1 for success
@@ -393,9 +398,13 @@ func (m *InstrumentedState) handleRMWOps(insn, opcode uint32) error {
 			exec.StoreSubWord(m.state.GetMemory(), addr, byteLength, val, m.memoryTracker)
 
 			retVal = 1
+
+			m.statsTracker.trackSCSuccess(threadId, m.GetState().GetStep())
 		} else {
 			// Atomic update failed, return 0 for failure
 			retVal = 0
+
+			m.statsTracker.trackSCFailure(threadId, m.GetState().GetStep())
 		}
 	default:
 		panic(fmt.Sprintf("Invalid instruction passed to handleRMWOps (opcode %08x)", opcode))
@@ -419,6 +428,7 @@ func (m *InstrumentedState) onWaitComplete(thread *ThreadState, isTimedOut bool)
 		v1 = exec.MipsETIMEDOUT
 	}
 	exec.HandleSyscallUpdates(&thread.Cpu, &thread.Registers, v0, v1)
+	m.statsTracker.trackWakeup()
 }
 
 func (m *InstrumentedState) preemptThread(thread *ThreadState) bool {
@@ -447,6 +457,8 @@ func (m *InstrumentedState) preemptThread(thread *ThreadState) bool {
 	}
 
 	m.state.StepsSinceLastContextSwitch = 0
+
+	m.statsTracker.trackThreadActivated(m.state.GetCurrentThread().ThreadId, m.state.GetStep())
 	return changeDirections
 }
 

cannon/mipsevm/multithreaded/stats.go

+package multithreaded
+
+import (
+	lru "github.com/hashicorp/golang-lru/v2/simplelru"
+
+	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
+)
+
+// Define stats interface
+type StatsTracker interface {
+	trackLL(threadId Word, step uint64)
+	trackSCSuccess(threadId Word, step uint64)
+	trackSCFailure(threadId Word, step uint64)
+	trackReservationInvalidation()
+	trackForcedPreemption()
+	trackWakeupTraversalStart()
+	trackWakeup()
+	trackWakeupFail()
+	trackThreadActivated(tid Word, step uint64)
+	populateDebugInfo(debugInfo *mipsevm.DebugInfo)
+}
+
+// Noop implementation for when tracking is disabled
+type noopStatsTracker struct{}
+
+func NoopStatsTracker() StatsTracker {
+	return &noopStatsTracker{}
+}
+
+func (s *noopStatsTracker) trackLL(threadId Word, step uint64)             {}
+func (s *noopStatsTracker) trackSCSuccess(threadId Word, step uint64)      {}
+func (s *noopStatsTracker) trackSCFailure(threadId Word, step uint64)      {}
+func (s *noopStatsTracker) trackReservationInvalidation()                  {}
+func (s *noopStatsTracker) trackForcedPreemption()                         {}
+func (s *noopStatsTracker) trackWakeupTraversalStart()                     {}
+func (s *noopStatsTracker) trackWakeup()                                   {}
+func (s *noopStatsTracker) trackWakeupFail()                               {}
+func (s *noopStatsTracker) trackThreadActivated(tid Word, step uint64)     {}
+func (s *noopStatsTracker) populateDebugInfo(debugInfo *mipsevm.DebugInfo) {}
+
+var _ StatsTracker = (*noopStatsTracker)(nil)
+
+// Actual implementation
+type statsTrackerImpl struct {
+	// State
+	lastLLStepByThread    *lru.LRU[Word, uint64]
+	isWakeupTraversal     bool
+	activeThreadId        Word
+	lastActiveStepThread0 uint64
+	// Stats
+	rmwSuccessCount        uint64
+	rmwFailCount           uint64
+	maxStepsBetweenLLAndSC uint64
+	// Tracks RMW reservation invalidation due to reserved memory being accessed outside of the RMW sequence
+	reservationInvalidationCount uint64
+	forcedPreemptionCount        uint64
+	failedWakeupCount            uint64
+	idleStepCountThread0         uint64
+}
+
+func (s *statsTrackerImpl) populateDebugInfo(debugInfo *mipsevm.DebugInfo) {
+	debugInfo.RmwSuccessCount = s.rmwSuccessCount
+	debugInfo.RmwFailCount = s.rmwFailCount
+	debugInfo.MaxStepsBetweenLLAndSC = s.maxStepsBetweenLLAndSC
+	debugInfo.ReservationInvalidationCount = s.reservationInvalidationCount
+	debugInfo.ForcedPreemptionCount = s.forcedPreemptionCount
+	debugInfo.FailedWakeupCount = s.failedWakeupCount
+	debugInfo.IdleStepCountThread0 = s.idleStepCountThread0
+}
+
+func (s *statsTrackerImpl) trackLL(threadId Word, step uint64) {
+	s.lastLLStepByThread.Add(threadId, step)
+}
+
+func (s *statsTrackerImpl) trackSCSuccess(threadId Word, step uint64) {
+	s.rmwSuccessCount += 1
+	s.recordStepsBetweenLLAndSC(threadId, step)
+}
+
+func (s *statsTrackerImpl) trackSCFailure(threadId Word, step uint64) {
+	s.rmwFailCount += 1
+	s.recordStepsBetweenLLAndSC(threadId, step)
+}
+
+func (s *statsTrackerImpl) recordStepsBetweenLLAndSC(threadId Word, scStep uint64) {
+	// Track rmw steps if we have the last ll step in our cache
+	if llStep, ok := s.lastLLStepByThread.Get(threadId); ok {
+		diff := scStep - llStep
+		if diff > s.maxStepsBetweenLLAndSC {
+			s.maxStepsBetweenLLAndSC = diff
+		}
+		// Purge ll step since the RMW seq is now complete
+		s.lastLLStepByThread.Remove(threadId)
+	}
+}
+
+func (s *statsTrackerImpl) trackReservationInvalidation() {
+	s.reservationInvalidationCount += 1
+}
+
+func (s *statsTrackerImpl) trackForcedPreemption() {
+	s.forcedPreemptionCount += 1
+}
+
+func (s *statsTrackerImpl) trackWakeupTraversalStart() {
+	s.isWakeupTraversal = true
+}
+
+func (s *statsTrackerImpl) trackWakeup() {
+	s.isWakeupTraversal = false
+}
+
+func (s *statsTrackerImpl) trackWakeupFail() {
+	if s.isWakeupTraversal {
+		s.failedWakeupCount += 1
+	}
+	s.isWakeupTraversal = false
+}
+
+func (s *statsTrackerImpl) trackThreadActivated(tid Word, step uint64) {
+	if s.activeThreadId == Word(0) && tid != Word(0) {
+		// Thread 0 has been deactivated, start tracking to capture idle steps
+		s.lastActiveStepThread0 = step
+	} else if s.activeThreadId != Word(0) && tid == Word(0) {
+		// Thread 0 has been activated, record idle steps
+		idleSteps := step - s.lastActiveStepThread0
+		s.idleStepCountThread0 += idleSteps
+	}
+	s.activeThreadId = tid
+}
+
+func NewStatsTracker() StatsTracker {
+	return newStatsTracker(5)
+}
+
+func newStatsTracker(cacheSize int) StatsTracker {
+	llStepCache, err := lru.NewLRU[Word, uint64](cacheSize, nil)
+	if err != nil {
+		panic(err) // negative size parameter may produce an error
+	}
+
+	return &statsTrackerImpl{
+		lastLLStepByThread: llStepCache,
+	}
+}
+
+var _ StatsTracker = (*statsTrackerImpl)(nil)

cannon/mipsevm/multithreaded/stats_test.go

+package multithreaded
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/require"
+
+	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
+)
+
+func TestStatsTracker(t *testing.T) {
+	cases := []struct {
+		name       string
+		operations []Operation
+		expected   *mipsevm.DebugInfo
+	}{
+		{
+			name:       "Successful RMW operation",
+			operations: []Operation{ll(1, 3), scSuccess(1, 13)},
+			expected:   &mipsevm.DebugInfo{RmwSuccessCount: 1, MaxStepsBetweenLLAndSC: 10},
+		},
+		{
+			name:       "Failed RMW operation",
+			operations: []Operation{ll(1, 3), scFail(1, 13)},
+			expected:   &mipsevm.DebugInfo{RmwFailCount: 1, MaxStepsBetweenLLAndSC: 10},
+		},
+		{
+			name:       "Failed isolated sc op",
+			operations: []Operation{scFail(1, 13)},
+			expected:   &mipsevm.DebugInfo{RmwFailCount: 1},
+		},
+		{
+			name:       "Failed isolated sc op preceded by successful sc op",
+			operations: []Operation{ll(1, 1), scSuccess(1, 10), scFail(1, 23)},
+			expected:   &mipsevm.DebugInfo{RmwSuccessCount: 1, RmwFailCount: 1, MaxStepsBetweenLLAndSC: 9},
+		},
+		{
+			name:       "Multiple RMW operations",
+			operations: []Operation{ll(1, 1), scSuccess(1, 2), ll(2, 3), scFail(2, 5), ll(3, 6), scSuccess(3, 16), ll(2, 18), scSuccess(2, 20), ll(1, 21), scFail(1, 30)},
+			expected:   &mipsevm.DebugInfo{RmwSuccessCount: 3, RmwFailCount: 2, MaxStepsBetweenLLAndSC: 10},
+		},
+		{
+			name:       "Multiple RMW operations exceeding cache size",
+			operations: []Operation{ll(1, 1), ll(2, 2), ll(3, 3), ll(4, 4), scSuccess(4, 5), scFail(3, 6), scFail(2, 7), scFail(1, 8)},
+			expected:   &mipsevm.DebugInfo{RmwSuccessCount: 1, RmwFailCount: 3, MaxStepsBetweenLLAndSC: 5},
+		},
+		{
+			name:       "Interleaved RMW operations",
+			operations: []Operation{ll(1, 5), ll(2, 10), scSuccess(2, 15), scFail(1, 25)},
+			expected:   &mipsevm.DebugInfo{RmwSuccessCount: 1, RmwFailCount: 1, MaxStepsBetweenLLAndSC: 20},
+		},
+		{
+			name:       "Invalidate reservation",
+			operations: []Operation{invalidateReservation()},
+			expected:   &mipsevm.DebugInfo{ReservationInvalidationCount: 1},
+		},
+		{
+			name:       "Invalidate reservation multiple times",
+			operations: []Operation{invalidateReservation(), invalidateReservation()},
+			expected:   &mipsevm.DebugInfo{ReservationInvalidationCount: 2},
+		},
+		{
+			name:       "Force preemption",
+			operations: []Operation{forcePreempt()},
+			expected:   &mipsevm.DebugInfo{ForcedPreemptionCount: 1},
+		},
+		{
+			name:       "Force preemption multiple times",
+			operations: []Operation{forcePreempt(), forcePreempt()},
+			expected:   &mipsevm.DebugInfo{ForcedPreemptionCount: 2},
+		},
+		{
+			name:       "Successful wakeup traversal",
+			operations: []Operation{wakeupTraversal(), wakeup(), sleep(), wakeup()},
+			expected:   &mipsevm.DebugInfo{FailedWakeupCount: 0},
+		},
+		{
+			name:       "Failed wakeup traversal",
+			operations: []Operation{wakeupTraversal(), sleep(), wakeup(), sleep()},
+			expected:   &mipsevm.DebugInfo{FailedWakeupCount: 1},
+		},
+		{
+			name:       "Multiple failed wakeup traversals",
+			operations: []Operation{wakeupTraversal(), sleep(), wakeupTraversal(), sleep(), wakeupTraversal(), wakeup()},
+			expected:   &mipsevm.DebugInfo{FailedWakeupCount: 2},
+		},
+		{
+			name:       "Wakeups and sleeps outside of wakeup traversal",
+			operations: []Operation{sleep(), wakeup(), wakeup(), sleep()},
+			expected:   &mipsevm.DebugInfo{FailedWakeupCount: 0},
+		},
+		{
+			name:       "Preempt thread 0 for thread 0",
+			operations: []Operation{activateThread(0, 10), activateThread(0, 20), activateThread(0, 21)},
+			expected:   &mipsevm.DebugInfo{IdleStepCountThread0: 0},
+		},
+		{
+			name:       "Preempt thread 0 for different thread",
+			operations: []Operation{activateThread(1, 10), activateThread(0, 20), activateThread(0, 21), activateThread(1, 22), activateThread(0, 25)},
+			expected:   &mipsevm.DebugInfo{IdleStepCountThread0: 13},
+		},
+	}
+
+	for _, c := range cases {
+		t.Run(c.name, func(t *testing.T) {
+			stats := newStatsTracker(3)
+			for _, op := range c.operations {
+				op(stats)
+			}
+
+			// Validate expectations
+			actual := &mipsevm.DebugInfo{}
+			stats.populateDebugInfo(actual)
+			require.Equal(t, c.expected, actual)
+		})
+	}
+}
+
+type Operation func(tracker StatsTracker)
+
+func ll(threadId Word, step uint64) Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackLL(threadId, step)
+	}
+}
+
+func scSuccess(threadId Word, step uint64) Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackSCSuccess(threadId, step)
+	}
+}
+
+func scFail(threadId Word, step uint64) Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackSCFailure(threadId, step)
+	}
+}
+
+func invalidateReservation() Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackReservationInvalidation()
+	}
+}
+
+func forcePreempt() Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackForcedPreemption()
+	}
+}
+
+func wakeupTraversal() Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackWakeupTraversalStart()
+	}
+}
+
+func wakeup() Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackWakeup()
+	}
+}
+
+func sleep() Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackWakeupFail()
+	}
+}
+
+func activateThread(tid Word, step uint64) Operation {
+	return func(tracker StatsTracker) {
+		tracker.trackThreadActivated(tid, step)
+	}
+}

cannon/mipsevm/singlethreaded/instrumented.go

@@ -3,9 +3,10 @@ package singlethreaded
 import (
 	"io"
 
+	"github.com/ethereum/go-ethereum/common/hexutil"
+
 	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
 	"github.com/ethereum-optimism/optimism/cannon/mipsevm/exec"
-	"github.com/ethereum/go-ethereum/common/hexutil"
 )
 
 type InstrumentedState struct {
@@ -53,6 +54,10 @@ func (m *InstrumentedState) InitDebug() error {
 	return nil
 }
 
+func (m *InstrumentedState) EnableStats() {
+	//noop
+}
+
 func (m *InstrumentedState) Step(proof bool) (wit *mipsevm.StepWitness, err error) {
 	m.preimageOracle.Reset()
 	m.memoryTracker.Reset(proof)
@@ -102,6 +107,7 @@ func (m *InstrumentedState) GetDebugInfo() *mipsevm.DebugInfo {
 		MemoryUsed:          hexutil.Uint64(m.state.Memory.UsageRaw()),
 		NumPreimageRequests: m.preimageOracle.NumPreimageRequests(),
 		TotalPreimageSize:   m.preimageOracle.TotalPreimageSize(),
+		TotalSteps:          m.state.GetStep(),
 	}
 }
 

op-challenger/README.md

@@ -192,7 +192,7 @@ Prints the list of current claims in a dispute game.
   --l1-beacon=<L1_BEACON> \
   --l2-eth-rpc=<L2_ETH_RPC> \
   --rollup-rpc=<ROLLUP_RPC> \
-  --data-dir=<DATA_DIR> \
+  --datadir=<DATA_DIR> \
   --prestates-url=<PRESTATES_URL> \
   --run=<RUN_CONFIG>
 ```

op-challenger/game/fault/trace/outputs/output_asterisc.go

@@ -5,6 +5,9 @@ import (
 	"fmt"
 	"path/filepath"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
+
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/asterisc"
@@ -14,8 +17,6 @@ import (
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/types"
 	"github.com/ethereum-optimism/optimism/op-challenger/metrics"
 	"github.com/ethereum-optimism/optimism/op-service/eth"
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 func NewOutputAsteriscTraceAccessor(
@@ -41,7 +42,7 @@ func NewOutputAsteriscTraceAccessor(
 		if err != nil {
 			return nil, fmt.Errorf("failed to fetch asterisc local inputs: %w", err)
 		}
-		provider := asterisc.NewTraceProvider(logger, m.VmMetrics(cfg.VmType.String()), cfg, vmCfg, prestateProvider, asteriscPrestate, localInputs, subdir, depth)
+		provider := asterisc.NewTraceProvider(logger, m.ToTypedVmMetrics(cfg.VmType.String()), cfg, vmCfg, prestateProvider, asteriscPrestate, localInputs, subdir, depth)
 		return provider, nil
 	}
 

op-challenger/game/fault/trace/outputs/output_cannon.go

@@ -5,6 +5,9 @@ import (
 	"fmt"
 	"path/filepath"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
+
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/cannon"
@@ -14,8 +17,6 @@ import (
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/types"
 	"github.com/ethereum-optimism/optimism/op-challenger/metrics"
 	"github.com/ethereum-optimism/optimism/op-service/eth"
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 func NewOutputCannonTraceAccessor(
@@ -41,7 +42,7 @@ func NewOutputCannonTraceAccessor(
 		if err != nil {
 			return nil, fmt.Errorf("failed to fetch cannon local inputs: %w", err)
 		}
-		provider := cannon.NewTraceProvider(logger, m.VmMetrics(cfg.VmType.String()), cfg, serverExecutor, prestateProvider, cannonPrestate, localInputs, subdir, depth)
+		provider := cannon.NewTraceProvider(logger, m.ToTypedVmMetrics(cfg.VmType.String()), cfg, serverExecutor, prestateProvider, cannonPrestate, localInputs, subdir, depth)
 		return provider, nil
 	}
 

op-challenger/game/fault/trace/vm/executor.go

@@ -10,21 +10,20 @@ import (
 	"strings"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common/hexutil"
+	"github.com/ethereum/go-ethereum/log"
+
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/utils"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/types"
+	"github.com/ethereum-optimism/optimism/op-challenger/metrics"
 	"github.com/ethereum-optimism/optimism/op-service/jsonutil"
-	"github.com/ethereum/go-ethereum/common/hexutil"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 const (
 	debugFilename = "debug-info.json"
 )
 
-type Metricer interface {
-	RecordExecutionTime(t time.Duration)
-	RecordMemoryUsed(memoryUsed uint64)
-}
+type Metricer = metrics.TypedVmMetricer
 
 type Config struct {
 	// VM Configuration
@@ -139,8 +138,16 @@ func (e *Executor) DoGenerateProof(ctx context.Context, dir string, begin uint64
 		if info, err := jsonutil.LoadJSON[debugInfo](filepath.Join(dataDir, debugFilename)); err != nil {
 			e.logger.Warn("Failed to load debug metrics", "err", err)
 		} else {
-			e.metrics.RecordMemoryUsed(uint64(info.MemoryUsed))
 			memoryUsed = fmt.Sprintf("%d", uint64(info.MemoryUsed))
+			e.metrics.RecordMemoryUsed(uint64(info.MemoryUsed))
+			e.metrics.RecordSteps(info.Steps)
+			e.metrics.RecordRmwSuccessCount(uint64(info.RmwSuccessCount))
+			e.metrics.RecordRmwFailCount(uint64(info.RmwFailCount))
+			e.metrics.RecordMaxStepsBetweenLLAndSC(uint64(info.MaxStepsBetweenLLAndSC))
+			e.metrics.RecordReservationInvalidationCount(uint64(info.ReservationInvalidationCount))
+			e.metrics.RecordForcedPreemptionCount(uint64(info.ForcedPreemptionCount))
+			e.metrics.RecordFailedWakeupCount(uint64(info.FailedWakeupCount))
+			e.metrics.RecordIdleStepCountThread0(uint64(info.IdleStepCountThread0))
 		}
 	}
 	e.logger.Info("VM execution complete", "time", execTime, "memory", memoryUsed)
@@ -148,5 +155,13 @@ func (e *Executor) DoGenerateProof(ctx context.Context, dir string, begin uint64
 }
 
 type debugInfo struct {
-	MemoryUsed hexutil.Uint64 `json:"memory_used"`
+	MemoryUsed                   hexutil.Uint64 `json:"memory_used"`
+	Steps                        uint64         `json:"total_steps"`
+	RmwSuccessCount              uint64         `json:"rmw_success_count"`
+	RmwFailCount                 uint64         `json:"rmw_fail_count"`
+	MaxStepsBetweenLLAndSC       uint64         `json:"max_steps_between_ll_and_sc"`
+	ReservationInvalidationCount uint64         `json:"reservation_invalidation_count"`
+	ForcedPreemptionCount        uint64         `json:"forced_preemption_count"`
+	FailedWakeupCount            uint64         `json:"failed_wakeup_count"`
+	IdleStepCountThread0         uint64         `json:"idle_step_count_thread_0"`
 }

op-challenger/game/fault/trace/vm/executor_test.go

@@ -8,11 +8,16 @@ import (
 	"testing"
 	"time"
 
-	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/utils"
-	"github.com/ethereum-optimism/optimism/op-service/testlog"
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/stretchr/testify/require"
+
+	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
+	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/utils"
+	"github.com/ethereum-optimism/optimism/op-service/ioutil"
+	"github.com/ethereum-optimism/optimism/op-service/jsonutil"
+	"github.com/ethereum-optimism/optimism/op-service/testlog"
 )
 
 func TestGenerateProof(t *testing.T) {
@@ -39,8 +44,20 @@ func TestGenerateProof(t *testing.T) {
 		L2Claim:       common.Hash{0x44},
 		L2BlockNumber: big.NewInt(3333),
 	}
-	captureExec := func(t *testing.T, cfg Config, proofAt uint64) (string, string, map[string]string) {
-		m := &stubVmMetrics{}
+
+	info := &mipsevm.DebugInfo{
+		MemoryUsed:                   11,
+		TotalSteps:                   123455,
+		RmwSuccessCount:              12,
+		RmwFailCount:                 34,
+		MaxStepsBetweenLLAndSC:       56,
+		ReservationInvalidationCount: 78,
+		ForcedPreemptionCount:        910,
+		FailedWakeupCount:            1112,
+		IdleStepCountThread0:         1314,
+	}
+
+	captureExec := func(t *testing.T, cfg Config, proofAt uint64, m Metricer) (string, string, map[string]string) {
 		executor := NewExecutor(testlog.Logger(t, log.LevelInfo), m, cfg, NewOpProgramServerExecutor(testlog.Logger(t, log.LvlInfo)), prestate, inputs)
 		executor.selectSnapshot = func(logger log.Logger, dir string, absolutePreState string, i uint64, binary bool) (string, error) {
 			return input, nil
@@ -60,19 +77,25 @@ func TestGenerateProof(t *testing.T) {
 				args[a[i]] = a[i+1]
 				i += 2
 			}
+
+			// Write debuginfo file
+			debugPath := args["--debug-info"]
+			err := jsonutil.WriteJSON(info, ioutil.ToStdOutOrFileOrNoop(debugPath, 0o755))
+			require.NoError(t, err)
 			return nil
 		}
 		err := executor.GenerateProof(context.Background(), dir, proofAt)
 		require.NoError(t, err)
-		require.Equal(t, 1, m.executionTimeRecordCount, "Should record vm execution time")
 		return binary, subcommand, args
 	}
 
 	t.Run("Network", func(t *testing.T) {
+		m := newMetrics()
 		cfg.Network = "mainnet"
 		cfg.RollupConfigPath = ""
 		cfg.L2GenesisPath = ""
-		binary, subcommand, args := captureExec(t, cfg, 150_000_000)
+		cfg.DebugInfo = true
+		binary, subcommand, args := captureExec(t, cfg, 150_000_000, m)
 		require.DirExists(t, filepath.Join(dir, PreimagesDir))
 		require.DirExists(t, filepath.Join(dir, utils.ProofsDir))
 		require.DirExists(t, filepath.Join(dir, SnapsDir))
@@ -106,50 +129,139 @@ func TestGenerateProof(t *testing.T) {
 		require.Equal(t, inputs.L2OutputRoot.Hex(), args["--l2.outputroot"])
 		require.Equal(t, inputs.L2Claim.Hex(), args["--l2.claim"])
 		require.Equal(t, "3333", args["--l2.blocknumber"])
+
+		// Check metrics
+		validateMetrics(t, m, info, cfg)
 	})
 
 	t.Run("RollupAndGenesis", func(t *testing.T) {
+		m := newMetrics()
 		cfg.Network = ""
 		cfg.RollupConfigPath = "rollup.json"
 		cfg.L2GenesisPath = "genesis.json"
-		_, _, args := captureExec(t, cfg, 150_000_000)
+		cfg.DebugInfo = false
+		_, _, args := captureExec(t, cfg, 150_000_000, m)
 		require.NotContains(t, args, "--network")
 		require.Equal(t, cfg.RollupConfigPath, args["--rollup.config"])
 		require.Equal(t, cfg.L2GenesisPath, args["--l2.genesis"])
+		validateMetrics(t, m, info, cfg)
 	})
 
 	t.Run("NoStopAtWhenProofIsMaxUInt", func(t *testing.T) {
+		m := newMetrics()
 		cfg.Network = "mainnet"
 		cfg.RollupConfigPath = "rollup.json"
 		cfg.L2GenesisPath = "genesis.json"
-		_, _, args := captureExec(t, cfg, math.MaxUint64)
+		cfg.DebugInfo = true
+		_, _, args := captureExec(t, cfg, math.MaxUint64, m)
 		// stop-at would need to be one more than the proof step which would overflow back to 0
 		// so expect that it will be omitted. We'll ultimately want asterisc to execute until the program exits.
 		require.NotContains(t, args, "--stop-at")
+		validateMetrics(t, m, info, cfg)
 	})
 
 	t.Run("BinarySnapshots", func(t *testing.T) {
+		m := newMetrics()
 		cfg.Network = "mainnet"
 		cfg.BinarySnapshots = true
-		_, _, args := captureExec(t, cfg, 100)
+		_, _, args := captureExec(t, cfg, 100, m)
 		require.Equal(t, filepath.Join(dir, SnapsDir, "%d.bin.gz"), args["--snapshot-fmt"])
+		validateMetrics(t, m, info, cfg)
 	})
 
 	t.Run("JsonSnapshots", func(t *testing.T) {
+		m := newMetrics()
 		cfg.Network = "mainnet"
 		cfg.BinarySnapshots = false
-		_, _, args := captureExec(t, cfg, 100)
+		_, _, args := captureExec(t, cfg, 100, m)
 		require.Equal(t, filepath.Join(dir, SnapsDir, "%d.json.gz"), args["--snapshot-fmt"])
+		validateMetrics(t, m, info, cfg)
 	})
 }
 
-type stubVmMetrics struct {
+func validateMetrics(t require.TestingT, m *capturingVmMetrics, expected *mipsevm.DebugInfo, cfg Config) {
+	require.Equal(t, 1, m.executionTimeRecordCount, "Should record vm execution time")
+
+	// Check metrics sourced from cannon.mipsevm.DebugInfo json file
+	if cfg.DebugInfo {
+		require.Equal(t, expected.MemoryUsed, m.memoryUsed)
+		require.Equal(t, expected.TotalSteps, m.steps)
+		require.Equal(t, expected.RmwSuccessCount, m.rmwSuccessCount)
+		require.Equal(t, expected.RmwFailCount, m.rmwFailCount)
+		require.Equal(t, expected.MaxStepsBetweenLLAndSC, m.maxStepsBetweenLLAndSC)
+		require.Equal(t, expected.ReservationInvalidationCount, m.reservationInvalidations)
+		require.Equal(t, expected.ForcedPreemptionCount, m.forcedPreemptions)
+		require.Equal(t, expected.FailedWakeupCount, m.failedWakeup)
+		require.Equal(t, expected.IdleStepCountThread0, m.idleStepsThread0)
+	} else {
+		// If debugInfo is disabled, json file should not be written and metrics should be zeroed out
+		require.Equal(t, hexutil.Uint64(0), m.memoryUsed)
+		require.Equal(t, uint64(0), m.steps)
+		require.Equal(t, uint64(0), m.rmwSuccessCount)
+		require.Equal(t, uint64(0), m.rmwFailCount)
+		require.Equal(t, uint64(0), m.maxStepsBetweenLLAndSC)
+		require.Equal(t, uint64(0), m.reservationInvalidations)
+		require.Equal(t, uint64(0), m.forcedPreemptions)
+		require.Equal(t, uint64(0), m.failedWakeup)
+		require.Equal(t, uint64(0), m.idleStepsThread0)
+	}
+}
+
+func newMetrics() *capturingVmMetrics {
+	return &capturingVmMetrics{}
+}
+
+type capturingVmMetrics struct {
 	executionTimeRecordCount int
+	memoryUsed               hexutil.Uint64
+	steps                    uint64
+	rmwSuccessCount          uint64
+	rmwFailCount             uint64
+	maxStepsBetweenLLAndSC   uint64
+	reservationInvalidations uint64
+	forcedPreemptions        uint64
+	failedWakeup             uint64
+	idleStepsThread0         uint64
 }
 
-func (c *stubVmMetrics) RecordExecutionTime(_ time.Duration) {
-	c.executionTimeRecordCount++
+func (c *capturingVmMetrics) RecordSteps(val uint64) {
+	c.steps = val
 }
 
-func (c *stubVmMetrics) RecordMemoryUsed(_ uint64) {
+func (c *capturingVmMetrics) RecordExecutionTime(t time.Duration) {
+	c.executionTimeRecordCount += 1
 }
+
+func (c *capturingVmMetrics) RecordMemoryUsed(memoryUsed uint64) {
+	c.memoryUsed = hexutil.Uint64(memoryUsed)
+}
+
+func (c *capturingVmMetrics) RecordRmwSuccessCount(val uint64) {
+	c.rmwSuccessCount = val
+}
+
+func (c *capturingVmMetrics) RecordRmwFailCount(val uint64) {
+	c.rmwFailCount = val
+}
+
+func (c *capturingVmMetrics) RecordMaxStepsBetweenLLAndSC(val uint64) {
+	c.maxStepsBetweenLLAndSC = val
+}
+
+func (c *capturingVmMetrics) RecordReservationInvalidationCount(val uint64) {
+	c.reservationInvalidations = val
+}
+
+func (c *capturingVmMetrics) RecordForcedPreemptionCount(val uint64) {
+	c.forcedPreemptions = val
+}
+
+func (c *capturingVmMetrics) RecordFailedWakeupCount(val uint64) {
+	c.failedWakeup = val
+}
+
+func (c *capturingVmMetrics) RecordIdleStepCountThread0(val uint64) {
+	c.idleStepsThread0 = val
+}
+
+var _ Metricer = (*capturingVmMetrics)(nil)

op-challenger/metrics/metrics.go

@@ -2,15 +2,15 @@ package metrics
 
 import (
 	"io"
-	"time"
 
-	"github.com/ethereum-optimism/optimism/op-service/httputil"
-	"github.com/ethereum-optimism/optimism/op-service/sources/caching"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/ethclient"
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/prometheus/client_golang/prometheus"
 
+	"github.com/ethereum-optimism/optimism/op-service/httputil"
+	"github.com/ethereum-optimism/optimism/op-service/sources/caching"
+
 	contractMetrics "github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts/metrics"
 	opmetrics "github.com/ethereum-optimism/optimism/op-service/metrics"
 	txmetrics "github.com/ethereum-optimism/optimism/op-service/txmgr/metrics"
@@ -33,6 +33,9 @@ type Metricer interface {
 	// Record contract metrics
 	contractMetrics.ContractMetricer
 
+	// Record Vm metrics
+	VmMetricer
+
 	RecordActedL1Block(n uint64)
 
 	RecordGameStep()
@@ -59,9 +62,7 @@ type Metricer interface {
 	IncIdleExecutors()
 	DecIdleExecutors()
 
-	// Record vm execution metrics
-	VmMetricer
-	VmMetrics(vmType string) *VmMetrics
+	ToTypedVmMetrics(vmType string) TypedVmMetricer
 }
 
 // Metrics implementation must implement RegistryMetricer to allow the metrics server to work.
@@ -75,11 +76,12 @@ type Metrics struct {
 	txmetrics.TxMetrics
 	*opmetrics.CacheMetrics
 	*contractMetrics.ContractMetrics
+	*VmMetrics
 
-	info prometheus.GaugeVec
+	info *prometheus.GaugeVec
 	up   prometheus.Gauge
 
-	executors prometheus.GaugeVec
+	executors *prometheus.GaugeVec
 
 	bondClaimFailures prometheus.Counter
 	bondsClaimed      prometheus.Counter
@@ -96,10 +98,8 @@ type Metrics struct {
 
 	claimResolutionTime prometheus.Histogram
 	gameActTime         prometheus.Histogram
-	vmExecutionTime     *prometheus.HistogramVec
-	vmMemoryUsed        *prometheus.HistogramVec
 
-	trackedGames  prometheus.GaugeVec
+	trackedGames  *prometheus.GaugeVec
 	inflightGames prometheus.Gauge
 }
 
@@ -124,7 +124,9 @@ func NewMetrics() *Metrics {
 
 		ContractMetrics: contractMetrics.MakeContractMetrics(Namespace, factory),
 
-		info: *factory.NewGaugeVec(prometheus.GaugeOpts{
+		VmMetrics: NewVmMetrics(Namespace, factory),
+
+		info: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: Namespace,
 			Name:      "info",
 			Help:      "Pseudo-metric tracking version and config info",
@@ -136,7 +138,7 @@ func NewMetrics() *Metrics {
 			Name:      "up",
 			Help:      "1 if the op-challenger has finished starting up",
 		}),
-		executors: *factory.NewGaugeVec(prometheus.GaugeOpts{
+		executors: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: Namespace,
 			Name:      "executors",
 			Help:      "Number of active and idle executors",
@@ -172,21 +174,6 @@ func NewMetrics() *Metrics {
 				[]float64{1.0, 2.0, 5.0, 10.0},
 				prometheus.ExponentialBuckets(30.0, 2.0, 14)...),
 		}),
-		vmExecutionTime: factory.NewHistogramVec(prometheus.HistogramOpts{
-			Namespace: Namespace,
-			Name:      "vm_execution_time",
-			Help:      "Time (in seconds) to execute the fault proof VM",
-			Buckets: append(
-				[]float64{1.0, 10.0},
-				prometheus.ExponentialBuckets(30.0, 2.0, 14)...),
-		}, []string{"vm"}),
-		vmMemoryUsed: factory.NewHistogramVec(prometheus.HistogramOpts{
-			Namespace: Namespace,
-			Name:      "vm_memory_used",
-			Help:      "Memory used (in bytes) to execute the fault proof VM",
-			// 100MiB increments from 0 to 1.5GiB
-			Buckets: prometheus.LinearBuckets(0, 1024*1024*100, 15),
-		}, []string{"vm"}),
 		bondClaimFailures: factory.NewCounter(prometheus.CounterOpts{
 			Namespace: Namespace,
 			Name:      "claim_failures",
@@ -212,7 +199,7 @@ func NewMetrics() *Metrics {
 			Name:      "preimage_count",
 			Help:      "Number of large preimage proposals being tracked by the challenger",
 		}),
-		trackedGames: *factory.NewGaugeVec(prometheus.GaugeOpts{
+		trackedGames: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: Namespace,
 			Name:      "tracked_games",
 			Help:      "Number of games being tracked by the challenger",
@@ -292,14 +279,6 @@ func (m *Metrics) RecordBondClaimed(amount uint64) {
 	m.bondsClaimed.Add(float64(amount))
 }
 
-func (m *Metrics) RecordVmExecutionTime(vmType string, dur time.Duration) {
-	m.vmExecutionTime.WithLabelValues(vmType).Observe(dur.Seconds())
-}
-
-func (m *Metrics) RecordVmMemoryUsed(vmType string, memoryUsed uint64) {
-	m.vmMemoryUsed.WithLabelValues(vmType).Observe(float64(memoryUsed))
-}
-
 func (m *Metrics) RecordClaimResolutionTime(t float64) {
 	m.claimResolutionTime.Observe(t)
 }
@@ -342,6 +321,6 @@ func (m *Metrics) RecordGameUpdateCompleted() {
 	m.inflightGames.Sub(1)
 }
 
-func (m *Metrics) VmMetrics(vmType string) *VmMetrics {
-	return NewVmMetrics(m, vmType)
+func (m *Metrics) ToTypedVmMetrics(vmType string) TypedVmMetricer {
+	return NewTypedVmMetrics(m, vmType)
 }

op-challenger/metrics/noop.go

@@ -2,21 +2,23 @@ package metrics
 
 import (
 	"io"
-	"time"
 
-	contractMetrics "github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts/metrics"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/ethclient"
 	"github.com/ethereum/go-ethereum/log"
 
+	contractMetrics "github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts/metrics"
 	txmetrics "github.com/ethereum-optimism/optimism/op-service/txmgr/metrics"
 )
 
 type NoopMetricsImpl struct {
 	txmetrics.NoopTxMetrics
 	contractMetrics.NoopMetrics
+	NoopVmMetrics
 }
 
+var _ Metricer = (*NoopMetricsImpl)(nil)
+
 func (i *NoopMetricsImpl) StartBalanceMetrics(l log.Logger, client *ethclient.Client, account common.Address) io.Closer {
 	return nil
 }
@@ -39,10 +41,8 @@ func (*NoopMetricsImpl) RecordLargePreimageCount(_ int) {}
 func (*NoopMetricsImpl) RecordBondClaimFailed()   {}
 func (*NoopMetricsImpl) RecordBondClaimed(uint64) {}
 
-func (*NoopMetricsImpl) RecordVmExecutionTime(_ string, _ time.Duration) {}
-func (*NoopMetricsImpl) RecordVmMemoryUsed(_ string, _ uint64)           {}
-func (*NoopMetricsImpl) RecordClaimResolutionTime(t float64)             {}
-func (*NoopMetricsImpl) RecordGameActTime(t float64)                     {}
+func (*NoopMetricsImpl) RecordClaimResolutionTime(t float64) {}
+func (*NoopMetricsImpl) RecordGameActTime(t float64)         {}
 
 func (*NoopMetricsImpl) RecordGamesStatus(inProgress, defenderWon, challengerWon int) {}
 
@@ -57,6 +57,6 @@ func (*NoopMetricsImpl) DecIdleExecutors()   {}
 func (*NoopMetricsImpl) CacheAdd(_ string, _ int, _ bool) {}
 func (*NoopMetricsImpl) CacheGet(_ string, _ bool)        {}
 
-func (m *NoopMetricsImpl) VmMetrics(vmType string) *VmMetrics {
-	return NewVmMetrics(m, vmType)
+func (m *NoopMetricsImpl) ToTypedVmMetrics(vmType string) TypedVmMetricer {
+	return NewTypedVmMetrics(m, vmType)
 }

op-challenger/metrics/vm.go

 package metrics
 
-import "time"
+import (
+	"time"
+
+	"github.com/prometheus/client_golang/prometheus"
+
+	"github.com/ethereum-optimism/optimism/op-service/metrics"
+)
 
 type VmMetricer interface {
 	RecordVmExecutionTime(vmType string, t time.Duration)
 	RecordVmMemoryUsed(vmType string, memoryUsed uint64)
+	RecordVmRmwSuccessCount(vmType string, val uint64)
+	RecordVmSteps(vmType string, val uint64)
+	RecordVmRmwFailCount(vmType string, val uint64)
+	RecordVmMaxStepsBetweenLLAndSC(vmType string, val uint64)
+	RecordVmReservationInvalidationCount(vmType string, val uint64)
+	RecordVmForcedPreemptionCount(vmType string, val uint64)
+	RecordVmFailedWakeupCount(vmType string, val uint64)
+	RecordVmIdleStepCountThread0(vmType string, val uint64)
+}
+
+// TypedVmMetricer matches VmMetricer except the vmType parameter is already baked in and not supplied to each method
+type TypedVmMetricer interface {
+	RecordExecutionTime(t time.Duration)
+	RecordMemoryUsed(memoryUsed uint64)
+	RecordSteps(val uint64)
+	RecordRmwSuccessCount(val uint64)
+	RecordRmwFailCount(val uint64)
+	RecordMaxStepsBetweenLLAndSC(val uint64)
+	RecordReservationInvalidationCount(val uint64)
+	RecordForcedPreemptionCount(val uint64)
+	RecordFailedWakeupCount(val uint64)
+	RecordIdleStepCountThread0(val uint64)
 }
 
 type VmMetrics struct {
-	m      VmMetricer
-	vmType string
+	vmExecutionTime            *prometheus.HistogramVec
+	vmMemoryUsed               *prometheus.HistogramVec
+	vmSteps                    *prometheus.GaugeVec
+	vmRmwSuccessCount          *prometheus.GaugeVec
+	vmRmwFailCount             *prometheus.GaugeVec
+	vmMaxStepsBetweenLLAndSC   *prometheus.GaugeVec
+	vmReservationInvalidations *prometheus.GaugeVec
+	vmForcedPreemptions        *prometheus.GaugeVec
+	vmFailedWakeup             *prometheus.GaugeVec
+	vmIdleStepsThread0         *prometheus.GaugeVec
+}
+
+var _ VmMetricer = (*VmMetrics)(nil)
+
+func (m *VmMetrics) RecordVmExecutionTime(vmType string, dur time.Duration) {
+	m.vmExecutionTime.WithLabelValues(vmType).Observe(dur.Seconds())
+}
+
+func (m *VmMetrics) RecordVmMemoryUsed(vmType string, memoryUsed uint64) {
+	m.vmMemoryUsed.WithLabelValues(vmType).Observe(float64(memoryUsed))
+}
+
+func (m *VmMetrics) RecordVmSteps(vmType string, val uint64) {
+	m.vmSteps.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmRmwSuccessCount(vmType string, val uint64) {
+	m.vmRmwSuccessCount.WithLabelValues(vmType).Set(float64(val))
 }
 
-func NewVmMetrics(m VmMetricer, vmType string) *VmMetrics {
+func (m *VmMetrics) RecordVmRmwFailCount(vmType string, val uint64) {
+	m.vmRmwFailCount.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmMaxStepsBetweenLLAndSC(vmType string, val uint64) {
+	m.vmMaxStepsBetweenLLAndSC.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmReservationInvalidationCount(vmType string, val uint64) {
+	m.vmReservationInvalidations.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmForcedPreemptionCount(vmType string, val uint64) {
+	m.vmForcedPreemptions.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmFailedWakeupCount(vmType string, val uint64) {
+	m.vmFailedWakeup.WithLabelValues(vmType).Set(float64(val))
+}
+
+func (m *VmMetrics) RecordVmIdleStepCountThread0(vmType string, val uint64) {
+	m.vmIdleStepsThread0.WithLabelValues(vmType).Set(float64(val))
+}
+
+func NewVmMetrics(namespace string, factory metrics.Factory) *VmMetrics {
 	return &VmMetrics{
-		m:      m,
-		vmType: vmType,
+		vmExecutionTime: factory.NewHistogramVec(prometheus.HistogramOpts{
+			Namespace: namespace,
+			Name:      "vm_execution_time",
+			Help:      "Time (in seconds) to execute the fault proof VM",
+			Buckets: append(
+				[]float64{1.0, 10.0},
+				prometheus.ExponentialBuckets(30.0, 2.0, 14)...),
+		}, []string{"vm"}),
+		vmMemoryUsed: factory.NewHistogramVec(prometheus.HistogramOpts{
+			Namespace: namespace,
+			Name:      "vm_memory_used",
+			Help:      "Memory used (in bytes) to execute the fault proof VM",
+			// 100MiB increments from 0 to 1.5GiB
+			Buckets: prometheus.LinearBuckets(0, 1024*1024*100, 15),
+		}, []string{"vm"}),
+		vmSteps: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_step_count",
+			Help:      "Number of steps executed during vm run",
+		}, []string{"vm"}),
+		vmRmwSuccessCount: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_rmw_success_count",
+			Help:      "Number of successful RMW instruction sequences during vm run",
+		}, []string{"vm"}),
+		vmRmwFailCount: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_rmw_fail_count",
+			Help:      "Number of failed RMW instruction sequences during vm run",
+		}, []string{"vm"}),
+		// Note: vmMaxStepsBetweenLLAndSC is not complete and may miss longer ranges for failed rmw sequences.
+		vmMaxStepsBetweenLLAndSC: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_max_steps_between_ll_and_sc",
+			Help:      "The maximum number of steps observed between matching ll(d) and sc(d) instructions during the vm run",
+		}, []string{"vm"}),
+		vmReservationInvalidations: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_reservation_invalidations",
+			Help:      "Number of memory reservations that were invalidated during vm run",
+		}, []string{"vm"}),
+		vmForcedPreemptions: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_forced_preemptions",
+			Help:      "Number of forced preemptions during vm run",
+		}, []string{"vm"}),
+		vmFailedWakeup: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_failed_wakeup",
+			Help:      "Number of failed wakesups during vm run",
+		}, []string{"vm"}),
+		vmIdleStepsThread0: factory.NewGaugeVec(prometheus.GaugeOpts{
+			Namespace: namespace,
+			Name:      "vm_idle_steps_thread0",
+			Help:      "Number of steps thread 0 is idle during vm run",
+		}, []string{"vm"}),
 	}
 }
 
-func (m *VmMetrics) RecordExecutionTime(dur time.Duration) {
+type NoopVmMetrics struct{}
+
+var _ VmMetricer = NoopVmMetrics{}
+
+func (n NoopVmMetrics) RecordVmExecutionTime(vmType string, t time.Duration)           {}
+func (n NoopVmMetrics) RecordVmMemoryUsed(vmType string, memoryUsed uint64)            {}
+func (n NoopVmMetrics) RecordVmSteps(vmType string, val uint64)                        {}
+func (n NoopVmMetrics) RecordVmRmwSuccessCount(vmType string, val uint64)              {}
+func (n NoopVmMetrics) RecordVmRmwFailCount(vmType string, val uint64)                 {}
+func (n NoopVmMetrics) RecordVmMaxStepsBetweenLLAndSC(vmType string, val uint64)       {}
+func (n NoopVmMetrics) RecordVmReservationInvalidationCount(vmType string, val uint64) {}
+func (n NoopVmMetrics) RecordVmForcedPreemptionCount(vmType string, val uint64)        {}
+func (n NoopVmMetrics) RecordVmFailedWakeupCount(vmType string, val uint64)            {}
+func (n NoopVmMetrics) RecordVmIdleStepCountThread0(vmType string, val uint64)         {}
+
+type typedVmMetricsImpl struct {
+	m      VmMetricer
+	vmType string
+}
+
+var _ TypedVmMetricer = (*typedVmMetricsImpl)(nil)
+
+func (m *typedVmMetricsImpl) RecordExecutionTime(dur time.Duration) {
 	m.m.RecordVmExecutionTime(m.vmType, dur)
 }
 
-func (m *VmMetrics) RecordMemoryUsed(memoryUsed uint64) {
+func (m *typedVmMetricsImpl) RecordMemoryUsed(memoryUsed uint64) {
 	m.m.RecordVmMemoryUsed(m.vmType, memoryUsed)
 }
+
+func (m *typedVmMetricsImpl) RecordSteps(val uint64) {
+	m.m.RecordVmSteps(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordRmwSuccessCount(val uint64) {
+	m.m.RecordVmRmwSuccessCount(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordRmwFailCount(val uint64) {
+	m.m.RecordVmRmwFailCount(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordMaxStepsBetweenLLAndSC(val uint64) {
+	m.m.RecordVmMaxStepsBetweenLLAndSC(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordReservationInvalidationCount(val uint64) {
+	m.m.RecordVmReservationInvalidationCount(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordForcedPreemptionCount(val uint64) {
+	m.m.RecordVmForcedPreemptionCount(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordFailedWakeupCount(val uint64) {
+	m.m.RecordVmFailedWakeupCount(m.vmType, val)
+}
+
+func (m *typedVmMetricsImpl) RecordIdleStepCountThread0(val uint64) {
+	m.m.RecordVmIdleStepCountThread0(m.vmType, val)
+}
+
+func NewTypedVmMetrics(m VmMetricer, vmType string) TypedVmMetricer {
+	return &typedVmMetricsImpl{
+		m:      m,
+		vmType: vmType,
+	}
+}

op-challenger/runner/metrics.go

@@ -3,9 +3,11 @@ package runner
 import (
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus"
+
 	contractMetrics "github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts/metrics"
+	"github.com/ethereum-optimism/optimism/op-challenger/metrics"
 	opmetrics "github.com/ethereum-optimism/optimism/op-service/metrics"
-	"github.com/prometheus/client_golang/prometheus"
 )
 
 const Namespace = "op_challenger_runner"
@@ -15,10 +17,9 @@ type Metrics struct {
 	registry *prometheus.Registry
 	factory  opmetrics.Factory
 	*contractMetrics.ContractMetrics
+	*metrics.VmMetrics
 
-	vmExecutionTime     *prometheus.HistogramVec
 	vmLastExecutionTime *prometheus.GaugeVec
-	vmMemoryUsed        *prometheus.HistogramVec
 	vmLastMemoryUsed    *prometheus.GaugeVec
 	successTotal        *prometheus.CounterVec
 	failuresTotal       *prometheus.CounterVec
@@ -40,27 +41,13 @@ func NewMetrics() *Metrics {
 		factory:  factory,
 
 		ContractMetrics: contractMetrics.MakeContractMetrics(Namespace, factory),
+		VmMetrics:       metrics.NewVmMetrics(Namespace, factory),
 
-		vmExecutionTime: factory.NewHistogramVec(prometheus.HistogramOpts{
-			Namespace: Namespace,
-			Name:      "vm_execution_time",
-			Help:      "Time (in seconds) to execute the fault proof VM",
-			Buckets: append(
-				[]float64{1.0, 10.0},
-				prometheus.ExponentialBuckets(30.0, 2.0, 14)...),
-		}, []string{"vm"}),
 		vmLastExecutionTime: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: Namespace,
 			Name:      "vm_last_execution_time",
 			Help:      "Time (in seconds) taken for the last execution of the fault proof VM",
 		}, []string{"vm"}),
-		vmMemoryUsed: factory.NewHistogramVec(prometheus.HistogramOpts{
-			Namespace: Namespace,
-			Name:      "vm_memory_used",
-			Help:      "Memory used (in bytes) to execute the fault proof VM",
-			// 100MiB increments from 0 to 1.5GiB
-			Buckets: prometheus.LinearBuckets(0, 1024*1024*100, 15),
-		}, []string{"vm"}),
 		vmLastMemoryUsed: factory.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: Namespace,
 			Name:      "vm_last_memory_used",
@@ -90,12 +77,12 @@ func (m *Metrics) Registry() *prometheus.Registry {
 
 func (m *Metrics) RecordVmExecutionTime(vmType string, dur time.Duration) {
 	val := dur.Seconds()
-	m.vmExecutionTime.WithLabelValues(vmType).Observe(val)
+	m.VmMetrics.RecordVmExecutionTime(vmType, dur)
 	m.vmLastExecutionTime.WithLabelValues(vmType).Set(val)
 }
 
 func (m *Metrics) RecordVmMemoryUsed(vmType string, memoryUsed uint64) {
-	m.vmMemoryUsed.WithLabelValues(vmType).Observe(float64(memoryUsed))
+	m.VmMetrics.RecordVmMemoryUsed(vmType, memoryUsed)
 	m.vmLastMemoryUsed.WithLabelValues(vmType).Set(float64(memoryUsed))
 }
 

op-challenger/runner/runner.go

@@ -12,6 +12,9 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
+
 	"github.com/ethereum-optimism/optimism/cannon/mipsevm"
 	"github.com/ethereum-optimism/optimism/op-challenger/config"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/contracts"
@@ -25,8 +28,6 @@ import (
 	opmetrics "github.com/ethereum-optimism/optimism/op-service/metrics"
 	"github.com/ethereum-optimism/optimism/op-service/sources"
 	"github.com/ethereum-optimism/optimism/op-service/sources/batching"
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 var (
@@ -35,9 +36,8 @@ var (
 
 type Metricer interface {
 	contractMetrics.ContractMetricer
+	metrics.VmMetricer
 
-	RecordVmExecutionTime(vmType string, t time.Duration)
-	RecordVmMemoryUsed(vmType string, memoryUsed uint64)
 	RecordFailure(vmType string)
 	RecordInvalid(vmType string)
 	RecordSuccess(vmType string)
@@ -159,7 +159,7 @@ func (r *Runner) runAndRecordOnce(ctx context.Context, runConfig RunConfig, clie
 }
 
 func (r *Runner) runOnce(ctx context.Context, logger log.Logger, name string, traceType types.TraceType, prestateHash common.Hash, localInputs utils.LocalGameInputs, dir string) error {
-	provider, err := createTraceProvider(ctx, logger, metrics.NewVmMetrics(r.m, name), r.cfg, prestateHash, traceType, localInputs, dir)
+	provider, err := createTraceProvider(ctx, logger, metrics.NewTypedVmMetrics(r.m, name), r.cfg, prestateHash, traceType, localInputs, dir)
 	if err != nil {
 		return fmt.Errorf("failed to create trace provider: %w", err)
 	}

op-e2e/e2eutils/disputegame/output_cannon_helper.go

@@ -9,6 +9,9 @@ import (
 	"path/filepath"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
+
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/cannon"
 	"github.com/ethereum-optimism/optimism/op-challenger/game/fault/trace/outputs"
@@ -25,8 +28,6 @@ import (
 	"github.com/ethereum-optimism/optimism/op-service/sources/batching"
 	"github.com/ethereum-optimism/optimism/op-service/sources/batching/rpcblock"
 	"github.com/ethereum-optimism/optimism/op-service/testlog"
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/log"
 )
 
 type OutputCannonGameHelper struct {
@@ -316,7 +317,7 @@ func (g *OutputCannonGameHelper) createCannonTraceProvider(ctx context.Context,
 		localContext = outputs.CreateLocalContext(pre, post)
 		dir := filepath.Join(cfg.Datadir, "cannon-trace")
 		subdir := filepath.Join(dir, localContext.Hex())
-		return cannon.NewTraceProviderForTest(logger, metrics.NoopMetrics.VmMetrics(types.TraceTypeCannon.String()), cfg, localInputs, subdir, g.MaxDepth(ctx)-splitDepth-1), nil
+		return cannon.NewTraceProviderForTest(logger, metrics.NoopMetrics.ToTypedVmMetrics(types.TraceTypeCannon.String()), cfg, localInputs, subdir, g.MaxDepth(ctx)-splitDepth-1), nil
 	})
 
 	claims, err := g.Game.GetAllClaims(ctx, rpcblock.Latest)

op-e2e/faultproofs/precompile_test.go

@@ -273,7 +273,7 @@ func runCannon(t *testing.T, ctx context.Context, sys *e2esys.System, inputs uti
 	cannonOpts(&cfg)
 
 	logger := testlog.Logger(t, log.LevelInfo).New("role", "cannon")
-	executor := vm.NewExecutor(logger, metrics.NoopMetrics.VmMetrics("cannon"), cfg.Cannon, vm.NewOpProgramServerExecutor(logger), cfg.CannonAbsolutePreState, inputs)
+	executor := vm.NewExecutor(logger, metrics.NoopMetrics.ToTypedVmMetrics("cannon"), cfg.Cannon, vm.NewOpProgramServerExecutor(logger), cfg.CannonAbsolutePreState, inputs)
 
 	t.Log("Running cannon")
 	err := executor.DoGenerateProof(ctx, proofsDir, math.MaxUint, math.MaxUint, extraVmArgs...)