Event based pprof (ethereum#732)

* feature

* Save pprof to /tmp

---------

Co-authored-by: Jerry <jerrycgh@gmail.com>

common/context.go

@@ -0,0 +1,32 @@
+package common
+
+import (
+	"context"
+
+	unique "github.com/ethereum/go-ethereum/common/set"
+)
+
+type key struct{}
+
+var (
+	labelsKey key
+)
+
+func WithLabels(ctx context.Context, labels ...string) context.Context {
+	if len(labels) == 0 {
+		return ctx
+	}
+
+	labels = append(labels, Labels(ctx)...)
+
+	return context.WithValue(ctx, labelsKey, unique.Deduplicate(labels))
+}
+
+func Labels(ctx context.Context) []string {
+	labels, ok := ctx.Value(labelsKey).([]string)
+	if !ok {
+		return nil
+	}
+
+	return labels
+}

common/context_test.go

@@ -0,0 +1,107 @@
+package common
+
+import (
+	"context"
+	"reflect"
+	"sort"
+	"testing"
+)
+
+func TestWithLabels(t *testing.T) {
+	t.Parallel()
+
+	cases := []struct {
+		name     string
+		initial  []string
+		new      []string
+		expected []string
+	}{
+		{
+			"nil-nil",
+			nil,
+			nil,
+			nil,
+		},
+
+		{
+			"nil-something",
+			nil,
+			[]string{"one", "two"},
+			[]string{"one", "two"},
+		},
+
+		{
+			"something-nil",
+			[]string{"one", "two"},
+			nil,
+			[]string{"one", "two"},
+		},
+
+		{
+			"something-something",
+			[]string{"one", "two"},
+			[]string{"three", "four"},
+			[]string{"one", "two", "three", "four"},
+		},
+
+		// deduplication
+		{
+			"with duplicates nil-something",
+			nil,
+			[]string{"one", "two", "one"},
+			[]string{"one", "two"},
+		},
+
+		{
+			"with duplicates something-nil",
+			[]string{"one", "two", "one"},
+			nil,
+			[]string{"one", "two"},
+		},
+
+		{
+			"with duplicates something-something",
+			[]string{"one", "two"},
+			[]string{"three", "one"},
+			[]string{"one", "two", "three"},
+		},
+
+		{
+			"with duplicates something-something",
+			[]string{"one", "two", "three"},
+			[]string{"three", "four", "two"},
+			[]string{"one", "two", "three", "four"},
+		},
+	}
+
+	for _, c := range cases {
+		c := c
+
+		t.Run(c.name, func(t *testing.T) {
+			t.Parallel()
+
+			ctx := context.Background()
+
+			ctx = WithLabels(ctx, c.initial...)
+			ctx = WithLabels(ctx, c.new...)
+
+			got := Labels(ctx)
+
+			if len(got) != len(c.expected) {
+				t.Errorf("case %s. expected %v, got %v", c.name, c.expected, got)
+
+				return
+			}
+
+			gotSorted := sort.StringSlice(got)
+			gotSorted.Sort()
+
+			expectedSorted := sort.StringSlice(c.expected)
+			expectedSorted.Sort()
+
+			if !reflect.DeepEqual(gotSorted, expectedSorted) {
+				t.Errorf("case %s. expected %v, got %v", c.name, expectedSorted, gotSorted)
+			}
+		})
+	}
+}

common/set/slice.go

@@ -9,3 +9,20 @@ func New[T comparable](slice []T) map[T]struct{} {
 
 	return m
 }
+
+func ToSlice[T comparable](m map[T]struct{}) []T {
+	slice := make([]T, len(m))
+
+	var i int
+
+	for k := range m {
+		slice[i] = k
+		i++
+	}
+
+	return slice
+}
+
+func Deduplicate[T comparable](slice []T) []T {
+	return ToSlice(New(slice))
+}

eth/tracers/api.go

@@ -1052,7 +1052,7 @@ func (api *API) TraceCall(ctx context.Context, args ethapi.TransactionArgs, bloc
 		}
 	}
 	// Execute the trace
-	msg, err := args.ToMessage(api.backend.RPCGasCap(), block.BaseFee())
+	msg, err := args.ToMessage(ctx, api.backend.RPCGasCap(), block.BaseFee())
 	if err != nil {
 		return nil, err
 	}

internal/ethapi/api.go

@@ -21,7 +21,11 @@ import (
 	"errors"
 	"fmt"
 	"math/big"
+	"os"
+	"path/filepath"
+	"runtime/pprof"
 	"strings"
+	"sync"
 	"time"
 
 	"github.com/davecgh/go-spew/spew"
@@ -1005,7 +1009,7 @@ func DoCall(ctx context.Context, b Backend, args TransactionArgs, blockNrOrHash
 	defer cancel()
 
 	// Get a new instance of the EVM.
-	msg, err := args.ToMessage(globalGasCap, header.BaseFee)
+	msg, err := args.ToMessage(ctx, globalGasCap, header.BaseFee)
 	if err != nil {
 		return nil, err
 	}
@@ -1028,15 +1032,83 @@ func DoCall(ctx context.Context, b Backend, args TransactionArgs, blockNrOrHash
 	}
 
 	// If the timer caused an abort, return an appropriate error message
+	timeoutMu.Lock()
 	if evm.Cancelled() {
+		timeoutErrors++
+
+		if timeoutErrors >= pprofThreshold {
+			timeoutNoErrors = 0
+
+			if !isRunning {
+				runProfile()
+			}
+
+			log.Warn("[eth_call] timeout",
+				"timeoutErrors", timeoutErrors,
+				"timeoutNoErrors", timeoutNoErrors,
+				"args", args,
+				"blockNrOrHash", blockNrOrHash,
+				"overrides", overrides,
+				"timeout", timeout,
+				"globalGasCap", globalGasCap)
+		}
+
+		timeoutMu.Unlock()
+
 		return nil, fmt.Errorf("execution aborted (timeout = %v)", timeout)
+	} else {
+		if timeoutErrors >= pprofStopThreshold {
+			timeoutErrors = 0
+			timeoutNoErrors = 0
+
+			if isRunning {
+				pprof.StopCPUProfile()
+				isRunning = false
+			}
+		}
+	}
+
+	if isRunning && time.Since(pprofTime) >= pprofDuration {
+		timeoutErrors = 0
+		timeoutNoErrors = 0
+
+		pprof.StopCPUProfile()
+
+		isRunning = false
 	}
+
+	timeoutMu.Unlock()
+
 	if err != nil {
 		return result, fmt.Errorf("err: %w (supplied gas %d)", err, msg.Gas())
 	}
+
 	return result, nil
 }
 
+func runProfile() {
+	pprofTime = time.Now()
+
+	name := fmt.Sprintf("profile_eth_call-count-%d-time-%s.prof",
+		number, pprofTime.Format("2006-01-02-15-04-05"))
+
+	name = filepath.Join(os.TempDir(), name)
+
+	f, err := os.Create(name)
+	if err != nil {
+		log.Error("[eth_call] can't create profile file", "name", name, "err", err)
+		return
+	}
+
+	if err = pprof.StartCPUProfile(f); err != nil {
+		log.Error("[eth_call] can't start profiling", "name", name, "err", err)
+		return
+	}
+
+	isRunning = true
+	number++
+}
+
 func newRevertError(result *core.ExecutionResult) *revertError {
 	reason, errUnpack := abi.UnpackRevert(result.Revert())
 	err := errors.New("execution reverted")
@@ -1067,6 +1139,21 @@ func (e *revertError) ErrorData() interface{} {
 	return e.reason
 }
 
+var (
+	number          int
+	timeoutErrors   int // count for timeout errors
+	timeoutNoErrors int
+	timeoutMu       sync.Mutex
+	isRunning       bool
+	pprofTime       time.Time
+)
+
+const (
+	pprofThreshold     = 3
+	pprofStopThreshold = 3
+	pprofDuration      = time.Minute
+)
+
 // Call executes the given transaction on the state for the given block number.
 //
 // Additionally, the caller can specify a batch of contract for fields overriding.
@@ -1573,7 +1660,7 @@ func AccessList(ctx context.Context, b Backend, blockNrOrHash rpc.BlockNumberOrH
 		statedb := db.Copy()
 		// Set the accesslist to the last al
 		args.AccessList = &accessList
-		msg, err := args.ToMessage(b.RPCGasCap(), header.BaseFee)
+		msg, err := args.ToMessage(ctx, b.RPCGasCap(), header.BaseFee)
 		if err != nil {
 			return nil, 0, nil, err
 		}

internal/ethapi/transaction_args.go

@@ -197,7 +197,7 @@ func (args *TransactionArgs) setDefaults(ctx context.Context, b Backend) error {
 // ToMessage converts the transaction arguments to the Message type used by the
 // core evm. This method is used in calls and traces that do not require a real
 // live transaction.
-func (args *TransactionArgs) ToMessage(globalGasCap uint64, baseFee *big.Int) (types.Message, error) {
+func (args *TransactionArgs) ToMessage(_ context.Context, globalGasCap uint64, baseFee *big.Int) (types.Message, error) {
 	// Reject invalid combinations of pre- and post-1559 fee styles
 	if args.GasPrice != nil && (args.MaxFeePerGas != nil || args.MaxPriorityFeePerGas != nil) {
 		return types.Message{}, errors.New("both gasPrice and (maxFeePerGas or maxPriorityFeePerGas) specified")