Profile only SequenceTransactions [NIT-2578]

execution/gethexec/executionengine.go

@@ -13,10 +13,15 @@ package gethexec
 */
 import "C"
 import (
+	"bytes"
 	"context"
 	"encoding/binary"
 	"errors"
 	"fmt"
+	"os"
+	"path"
+	"runtime/pprof"
+	"runtime/trace"
 	"sync"
 	"testing"
 	"time"
@@ -27,6 +32,7 @@ import (
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/params"
+	"github.com/google/uuid"
 	"github.com/offchainlabs/nitro/arbos"
 	"github.com/offchainlabs/nitro/arbos/arbosState"
 	"github.com/offchainlabs/nitro/arbos/arbostypes"
@@ -334,6 +340,44 @@ func (s *ExecutionEngine) SequenceTransactions(header *arbostypes.L1IncomingMess
 	})
 }
 
+// SequenceTransactionsWithProfiling runs SequenceTransactions with tracing and
+// CPU profiling enabled. If the block creation takes longer than 5 seconds, it
+// keeps both and prints out filenames in an error log line.
+func (s *ExecutionEngine) SequenceTransactionsWithProfiling(header *arbostypes.L1IncomingMessageHeader, txes types.Transactions, hooks *arbos.SequencingHooks) (*types.Block, error) {
+	pprofBuf, traceBuf := bytes.NewBuffer(nil), bytes.NewBuffer(nil)
+	if err := pprof.StartCPUProfile(pprofBuf); err != nil {
+		log.Error("Starting CPU profiling", "error", err)
+	}
+	if err := trace.Start(traceBuf); err != nil {
+		log.Error("Starting tracing", "error", err)
+	}
+	start := time.Now()
+	res, err := s.SequenceTransactions(header, txes, hooks)
+	elapsed := time.Since(start)
+	pprof.StopCPUProfile()
+	trace.Stop()
+	if elapsed > 2*time.Second {
+		writeAndLog(pprofBuf, traceBuf)
+		return res, err
+	}
+	return res, err
+}
+
+func writeAndLog(pprof, trace *bytes.Buffer) {
+	id := uuid.NewString()
+	pprofFile := path.Join(os.TempDir(), id+".pprof")
+	if err := os.WriteFile(pprofFile, pprof.Bytes(), 0o600); err != nil {
+		log.Error("Creating temporary file for pprof", "fileName", pprofFile, "error", err)
+		return
+	}
+	traceFile := path.Join(os.TempDir(), id+".trace")
+	if err := os.WriteFile(traceFile, trace.Bytes(), 0o600); err != nil {
+		log.Error("Creating temporary file for trace", "fileName", traceFile, "error", err)
+		return
+	}
+	log.Info("Block creation took longer than 5 seconds, created pprof and trace files", "pprof", pprofFile, "traceFile", traceFile)
+}
+
 func (s *ExecutionEngine) sequenceTransactionsWithBlockMutex(header *arbostypes.L1IncomingMessageHeader, txes types.Transactions, hooks *arbos.SequencingHooks) (*types.Block, error) {
 	lastBlockHeader, err := s.getCurrentHeader()
 	if err != nil {

execution/gethexec/sequencer.go

@@ -4,24 +4,18 @@
 package gethexec
 
 import (
-	"bytes"
 	"context"
 	"errors"
 	"fmt"
 	"math"
 	"math/big"
-	"os"
-	"path"
 	"runtime/debug"
-	"runtime/pprof"
-	"runtime/trace"
 	"strconv"
 	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
 
-	"github.com/google/uuid"
 	"github.com/offchainlabs/nitro/arbutil"
 	"github.com/offchainlabs/nitro/execution"
 	"github.com/offchainlabs/nitro/util/arbmath"
@@ -787,44 +781,6 @@ func (s *Sequencer) precheckNonces(queueItems []txQueueItem, totalBlockSize int)
 	return outputQueueItems
 }
 
-// createBlockWithProfiling runs create block with tracing and CPU profiling
-// enabled. If the block creation takes longer than 5 seconds, it keeps both
-// and prints out filenames in an error log line.
-func (s *Sequencer) createBlockWithProfiling(ctx context.Context) bool {
-	pprofBuf, traceBuf := bytes.NewBuffer(nil), bytes.NewBuffer(nil)
-	if err := pprof.StartCPUProfile(pprofBuf); err != nil {
-		log.Error("Starting CPU profiling", "error", err)
-	}
-	if err := trace.Start(traceBuf); err != nil {
-		log.Error("Starting tracing", "error", err)
-	}
-	start := time.Now()
-	res := s.createBlock(ctx)
-	elapsed := time.Since(start)
-	pprof.StopCPUProfile()
-	trace.Stop()
-	if elapsed > 2*time.Second {
-		writeAndLog(pprofBuf, traceBuf)
-		return res
-	}
-	return res
-}
-
-func writeAndLog(pprof, trace *bytes.Buffer) {
-	id := uuid.NewString()
-	pprofFile := path.Join(os.TempDir(), id+".pprof")
-	if err := os.WriteFile(pprofFile, pprof.Bytes(), 0o600); err != nil {
-		log.Error("Creating temporary file for pprof", "fileName", pprofFile, "error", err)
-		return
-	}
-	traceFile := path.Join(os.TempDir(), id+".trace")
-	if err := os.WriteFile(traceFile, trace.Bytes(), 0o600); err != nil {
-		log.Error("Creating temporary file for trace", "fileName", traceFile, "error", err)
-		return
-	}
-	log.Debug("Block creation took longer than 5 seconds, created pprof and trace files", "pprof", pprofFile, "traceFile", traceFile)
-}
-
 func (s *Sequencer) createBlock(ctx context.Context) (returnValue bool) {
 	var queueItems []txQueueItem
 	var totalBlockSize int
@@ -972,7 +928,15 @@ func (s *Sequencer) createBlock(ctx context.Context) (returnValue bool) {
 	}
 
 	start := time.Now()
-	block, err := s.execEngine.SequenceTransactions(header, txes, hooks)
+	var (
+		block *types.Block
+		err   error
+	)
+	if s.enableProfiling {
+		block, err = s.execEngine.SequenceTransactionsWithProfiling(header, txes, hooks)
+	} else {
+		block, err = s.execEngine.SequenceTransactions(header, txes, hooks)
+	}
 	elapsed := time.Since(start)
 	blockCreationTimer.Update(elapsed)
 	if elapsed >= time.Second*5 {
@@ -1168,13 +1132,7 @@ func (s *Sequencer) Start(ctxIn context.Context) error {
 
 	s.CallIteratively(func(ctx context.Context) time.Duration {
 		nextBlock := time.Now().Add(s.config().MaxBlockSpeed)
-		var madeBlock bool
-		if s.enableProfiling {
-			madeBlock = s.createBlockWithProfiling(ctx)
-		} else {
-			madeBlock = s.createBlock(ctx)
-		}
-		if madeBlock {
+		if s.createBlock(ctx) {
 			// Note: this may return a negative duration, but timers are fine with that (they treat negative durations as 0).
 			return time.Until(nextBlock)
 		}