diff --git a/common/common.go b/common/common.go index 21bce2f1..e8bc3ba4 100644 --- a/common/common.go +++ b/common/common.go @@ -48,6 +48,19 @@ type Profile struct { Simulation uint64 RedisUpdate uint64 Total uint64 + + // Redis profiling + RedisSavePayload uint64 + RedisUpdateTopBid uint64 + RedisUpdateFloor uint64 + + // Attributes + IsGzip bool + ContentType string + AboveFloorBid bool + SimulationSuccess bool + WasBidSaved bool + Optimistic bool } func (p *Profile) String() string { diff --git a/metrics/metrics.go b/metrics/metrics.go index c7ec13b6..da7113dd 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -19,16 +19,32 @@ const ( var ( meter otelapi.Meter + GetHeaderLatencyHistogram otelapi.Float64Histogram GetPayloadLatencyHistogram otelapi.Float64Histogram PublishBlockLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockReadLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockDecodeLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockPrechecksLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockSimulationLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockRedisLatencyHistogram otelapi.Float64Histogram + + SubmitNewBlockRedisPayloadLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockRedisTopBidLatencyHistogram otelapi.Float64Histogram + SubmitNewBlockRedisFloorLatencyHistogram otelapi.Float64Histogram + BuilderDemotionCount otelapi.Int64Counter - latencyBoundaries = otelapi.WithExplicitBucketBoundaries(func() []float64 { + // latencyBoundariesMs is the set of buckets of exponentially growing + // latencies that are ranging from 5ms up to 12s + latencyBoundariesMs = otelapi.WithExplicitBucketBoundaries(func() []float64 { base := math.Exp(math.Log(12.0) / 15.0) - res := make([]float64, 0, 31) - for i := -15; i < 16; i++ { - res = append(res, math.Pow(base, float64(i))) + res := make([]float64, 0, 48) + for i := -31; i < 16; i++ { + res = append(res, + 1000.0*math.Pow(base, float64(i)), + ) } return res }()...) @@ -37,8 +53,18 @@ var ( func Setup(ctx context.Context) error { for _, setup := range []func(context.Context) error{ setupMeter, // must come first + setupGetHeaderLatency, setupGetPayloadLatency, setupPublishBlockLatency, + setupSubmitNewBlockLatency, + setupSubmitNewBlockReadLatency, + setupSubmitNewBlockDecodeLatency, + setupSubmitNewBlockPrechecksLatency, + setupSubmitNewBlockSimulationLatency, + setupSubmitNewBlockRedisLatency, + setupSubmitNewBlockRedisPayloadLatency, + setupSubmitNewBlockRedisTopBidLatency, + setupSubmitNewBlockRedisFloorLatency, setupBuilderDemotionCount, } { if err := setup(ctx); err != nil { @@ -74,12 +100,26 @@ func setupMeter(ctx context.Context) error { return nil } -func setupGetPayloadLatency(ctx context.Context) error { +func setupGetHeaderLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "get_header_latency", + otelapi.WithDescription("statistics on the duration of getHeader requests execution"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + GetHeaderLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupGetPayloadLatency(_ context.Context) error { latency, err := meter.Float64Histogram( "get_payload_latency", otelapi.WithDescription("statistics on the duration of getPayload requests execution"), otelapi.WithUnit("ms"), - latencyBoundaries, + latencyBoundariesMs, ) GetPayloadLatencyHistogram = latency if err != nil { @@ -88,12 +128,12 @@ func setupGetPayloadLatency(ctx context.Context) error { return nil } -func setupPublishBlockLatency(ctx context.Context) error { +func setupPublishBlockLatency(_ context.Context) error { latency, err := meter.Float64Histogram( "publish_block_latency", otelapi.WithDescription("statistics on the duration of publishBlock requests sent to beacon node"), otelapi.WithUnit("ms"), - latencyBoundaries, + latencyBoundariesMs, ) PublishBlockLatencyHistogram = latency if err != nil { @@ -102,7 +142,133 @@ func setupPublishBlockLatency(ctx context.Context) error { return nil } -func setupBuilderDemotionCount(ctx context.Context) error { +func setupSubmitNewBlockLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_latency", + otelapi.WithDescription("statistics on the duration of submitNewBlock requests execution"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockReadLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_read_latency", + otelapi.WithDescription("statistics on the duration of reading the payload of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockReadLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockDecodeLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_decode_latency", + otelapi.WithDescription("statistics on the duration of decoding the payload of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockDecodeLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockPrechecksLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_prechecks_latency", + otelapi.WithDescription("statistics on the duration of prechecks (floor bid, signature etc.) of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockPrechecksLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockSimulationLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_simulation_latency", + otelapi.WithDescription("statistics on the block simulation duration of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockSimulationLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockRedisLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_redis_latency", + otelapi.WithDescription("statistics on the redis update duration of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockRedisLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockRedisPayloadLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_redis_payload_latency", + otelapi.WithDescription("statistics on the redis save payload duration during redis updates of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockRedisPayloadLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockRedisTopBidLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_redis_top_bid_latency", + otelapi.WithDescription("statistics on the redis update top bid duration during redis updates of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockRedisTopBidLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupSubmitNewBlockRedisFloorLatency(_ context.Context) error { + latency, err := meter.Float64Histogram( + "submit_new_block_redis_floor_latency", + otelapi.WithDescription("statistics on the redis update floor bid duration during redis updates of submitNewBlock requests"), + otelapi.WithUnit("ms"), + latencyBoundariesMs, + ) + SubmitNewBlockRedisFloorLatencyHistogram = latency + if err != nil { + return err + } + return nil +} + +func setupBuilderDemotionCount(_ context.Context) error { counter, err := meter.Int64Counter( "builder_demotion_count", otelapi.WithDescription("number of times a builder has been demoted"), diff --git a/services/api/service.go b/services/api/service.go index 192e3fd2..51684efd 100644 --- a/services/api/service.go +++ b/services/api/service.go @@ -41,6 +41,8 @@ import ( "github.com/pkg/errors" "github.com/prometheus/client_golang/prometheus/promhttp" "github.com/sirupsen/logrus" + "go.opentelemetry.io/otel/attribute" + otelapi "go.opentelemetry.io/otel/metric" uberatomic "go.uber.org/atomic" "golang.org/x/exp/slices" ) @@ -1180,6 +1182,12 @@ func (api *RelayAPI) handleGetHeader(w http.ResponseWriter, req *http.Request) { } log.Debug("getHeader request received") + defer func() { + metrics.GetHeaderLatencyHistogram.Record( + req.Context(), + float64(time.Since(requestTime).Milliseconds()), + ) + }() if slices.Contains(apiNoHeaderUserAgents, ua) { log.Info("rejecting getHeader by user agent") @@ -1233,6 +1241,7 @@ func (api *RelayAPI) handleGetHeader(w http.ResponseWriter, req *http.Request) { "value": value.String(), "blockHash": blockHash.String(), }).Info("bid delivered") + api.RespondOK(w, bid) } @@ -1876,6 +1885,9 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque "timestampRequestFin": time.Now().UTC().UnixMilli(), "requestDurationMs": time.Since(receivedAt).Milliseconds(), }).Info("request finished") + + // metrics + api.saveBlockSubmissionMetrics(pf, receivedAt) }() // If cancellations are disabled but builder requested it, return error @@ -1888,6 +1900,7 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque var err error var r io.Reader = req.Body isGzip := req.Header.Get("Content-Encoding") == "gzip" + pf.IsGzip = isGzip log = log.WithField("reqIsGzip", isGzip) if isGzip { r, err = gzip.NewReader(req.Body) @@ -1916,6 +1929,7 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque contentType := req.Header.Get("Content-Type") if contentType == "application/octet-stream" { log = log.WithField("reqContentType", "ssz") + pf.ContentType = "ssz" if err = payload.UnmarshalSSZ(requestPayloadBytes); err != nil { log.WithError(err).Warn("could not decode payload - SSZ") @@ -1926,11 +1940,13 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque return } log = log.WithField("reqContentType", "json") + pf.ContentType = "json" } else { log.Debug("received ssz-encoded payload") } } else { log = log.WithField("reqContentType", "json") + pf.ContentType = "json" if err := json.Unmarshal(requestPayloadBytes, payload); err != nil { log.WithError(err).Warn("could not decode payload - JSON") api.RespondError(w, http.StatusBadRequest, err.Error()) @@ -2046,6 +2062,7 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque return } + pf.AboveFloorBid = true log = log.WithField("timestampAfterCheckingFloorBid", time.Now().UTC().UnixMilli()) // Deferred saving of the builder submission to database (whenever this function ends) @@ -2118,9 +2135,11 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque }, } // With sufficient collateral, process the block optimistically. - if builderEntry.status.IsOptimistic && + optimistic := builderEntry.status.IsOptimistic && builderEntry.collateral.Cmp(submission.BidTrace.Value.ToBig()) >= 0 && - submission.BidTrace.Slot == api.optimisticSlot.Load() { + submission.BidTrace.Slot == api.optimisticSlot.Load() + pf.Optimistic = optimistic + if optimistic { go api.processOptimisticBlock(opts, simResultC) } else { // Simulate block (synchronously). @@ -2148,6 +2167,7 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque nextTime = time.Now().UTC() pf.Simulation = uint64(nextTime.Sub(prevTime).Microseconds()) + pf.SimulationSuccess = true prevTime = nextTime // If cancellations are enabled, then abort now if this submission is not the latest one @@ -2215,6 +2235,10 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque nextTime = time.Now().UTC() pf.RedisUpdate = uint64(nextTime.Sub(prevTime).Microseconds()) + pf.WasBidSaved = updateBidResult.WasBidSaved + pf.RedisSavePayload = uint64(updateBidResult.TimeSavePayload.Microseconds()) + pf.RedisUpdateTopBid = uint64(updateBidResult.TimeUpdateTopBid.Microseconds()) + pf.RedisUpdateFloor = uint64(updateBidResult.TimeUpdateFloor.Microseconds()) pf.Total = uint64(nextTime.Sub(receivedAt).Microseconds()) // All done, log with profiling information @@ -2228,6 +2252,80 @@ func (api *RelayAPI) handleSubmitNewBlock(w http.ResponseWriter, req *http.Reque w.WriteHeader(http.StatusOK) } +func (api *RelayAPI) saveBlockSubmissionMetrics(pf common.Profile, receivedTime time.Time) { + if pf.PayloadLoad > 0 { + metrics.SubmitNewBlockReadLatencyHistogram.Record( + context.Background(), + float64(pf.PayloadLoad)/1000, + otelapi.WithAttributes(attribute.Bool("isGzip", pf.IsGzip)), + ) + } + if pf.Decode > 0 { + metrics.SubmitNewBlockDecodeLatencyHistogram.Record( + context.Background(), + float64(pf.Decode)/1000, + otelapi.WithAttributes(attribute.String("contentType", pf.ContentType)), + ) + } + + if pf.Prechecks > 0 { + metrics.SubmitNewBlockPrechecksLatencyHistogram.Record( + context.Background(), + float64(pf.Prechecks)/1000, + ) + } + + if pf.Simulation > 0 { + metrics.SubmitNewBlockSimulationLatencyHistogram.Record( + context.Background(), + float64(pf.Simulation)/1000, + otelapi.WithAttributes(attribute.Bool("simulationSuccess", pf.SimulationSuccess)), + ) + } + + if pf.RedisUpdate > 0 { + metrics.SubmitNewBlockRedisLatencyHistogram.Record( + context.Background(), + float64(pf.RedisUpdate)/1000, + otelapi.WithAttributes(attribute.Bool("wasBidSaved", pf.WasBidSaved)), + ) + } + + if pf.RedisSavePayload > 0 { + metrics.SubmitNewBlockRedisPayloadLatencyHistogram.Record( + context.Background(), + float64(pf.RedisSavePayload)/1000, + ) + } + + if pf.RedisUpdateTopBid > 0 { + metrics.SubmitNewBlockRedisTopBidLatencyHistogram.Record( + context.Background(), + float64(pf.RedisUpdateTopBid)/1000, + ) + } + + if pf.RedisUpdateFloor > 0 { + metrics.SubmitNewBlockRedisFloorLatencyHistogram.Record( + context.Background(), + float64(pf.RedisUpdateFloor)/1000, + ) + } + + metrics.SubmitNewBlockLatencyHistogram.Record( + context.Background(), + float64(time.Since(receivedTime).Milliseconds()), + otelapi.WithAttributes( + attribute.String("contentType", pf.ContentType), + attribute.Bool("isGzip", pf.IsGzip), + attribute.Bool("aboveFloorBid", pf.AboveFloorBid), + attribute.Bool("simulationSuccess", pf.SimulationSuccess), + attribute.Bool("wasBidSaved", pf.WasBidSaved), + attribute.Bool("optimistic", pf.Optimistic), + ), + ) +} + // --------------- // // INTERNAL APIS