Add metrics to measure the time spend on EC checkpointing (#962)

Meter the time spent on EC checkpointing tagged by status

Author: masih

host.go

@@ -20,6 +20,7 @@ import (
 	"github.com/filecoin-project/go-f3/manifest"
 	pubsub "github.com/libp2p/go-libp2p-pubsub"
 	"github.com/libp2p/go-libp2p/core/peer"
+	"go.opentelemetry.io/otel/metric"
 	"go.uber.org/multierr"
 	"golang.org/x/sync/errgroup"
 )
@@ -287,13 +288,16 @@ func (h *gpbftRunner) Start(ctx context.Context) (_err error) {
 					return errors.New("cert store subscription to finalize tipsets was closed unexpectedly")
 				}
 				if h.manifest.EC.Finalize {
+					start := time.Now()
 					key := cert.ECChain.Head().Key
-					if err := h.ec.Finalize(h.runningCtx, key); err != nil {
+					err := h.ec.Finalize(h.runningCtx, key)
+					if err != nil {
 						// There is not much we can do here other than logging. The next instance start
 						// will effectively retry checkpointing the latest finalized tipset. This error
 						// will not impact the selection of next instance chain.
 						log.Errorf("error while finalizing decision at EC: %+v", err)
 					}
+					metrics.ecFinalizeTime.Record(context.Background(), time.Since(start).Seconds(), metric.WithAttributes(attrStatusFromErr(err)))
 				} else {
 					ts := cert.ECChain.Head()
 					log.Debugw("skipping finalization of a new head because the current manifest specifies that tipsets should not be finalized",

metrics.go

@@ -54,6 +54,7 @@ var metrics = struct {
 	partialMessagesDropped   metric.Int64Counter
 	partialMessageInstances  metric.Int64UpDownCounter
 	partialValidationCache   metric.Int64Counter
+	ecFinalizeTime           metric.Float64Histogram
 }{
 	headDiverged:      measurements.Must(meter.Int64Counter("f3_head_diverged", metric.WithDescription("Number of times we encountered the head has diverged from base scenario."))),
 	reconfigured:      measurements.Must(meter.Int64Counter("f3_reconfigured", metric.WithDescription("Number of times we reconfigured due to new manifest being delivered."))),
@@ -85,6 +86,11 @@ var metrics = struct {
 		metric.WithDescription("Number of instances with partial GPBFT messages pending fulfilment."))),
 	partialValidationCache: measurements.Must(meter.Int64Counter("f3_partial_validation_cache",
 		metric.WithDescription("The number of times partial validation cache resulted in hit or miss."))),
+	ecFinalizeTime: measurements.Must(meter.Float64Histogram("f3_ec_finalize_time",
+		metric.WithDescription("Histogram of the number of seconds spent checkpointing an F3 decision in EC tagged by status"),
+		metric.WithExplicitBucketBoundaries(0.001, 0.002, 0.003, 0.005, 0.01, 0.02, 0.03, 0.04, 0.05, 0.1, 0.2, 0.3, 0.4, 0.5, 1.0, 10.0),
+		metric.WithUnit("s"),
+	)),
 }
 
 func recordValidatedMessage(ctx context.Context, msg gpbft.ValidatedMessage) {