Add more metrics to the relay (#817)

bgs/bgs.go

@@ -876,14 +876,19 @@ func (bgs *BGS) handleFedEvent(ctx context.Context, host *models.PDS, env *event
 		repoCommitsReceivedCounter.WithLabelValues(host.Host).Add(1)
 		evt := env.RepoCommit
 		log.Debugw("bgs got repo append event", "seq", evt.Seq, "pdsHost", host.Host, "repo", evt.Repo)
+
+		s := time.Now()
 		u, err := bgs.lookupUserByDid(ctx, evt.Repo)
+		userLookupDuration.Observe(time.Since(s).Seconds())
 		if err != nil {
 			if !errors.Is(err, gorm.ErrRecordNotFound) {
 				return fmt.Errorf("looking up event user: %w", err)
 			}
 
 			newUsersDiscovered.Inc()
+			start := time.Now()
 			subj, err := bgs.createExternalUser(ctx, evt.Repo)
+			newUserDiscoveryDuration.Observe(time.Since(start).Seconds())
 			if err != nil {
 				return fmt.Errorf("fed event create external user: %w", err)
 			}

bgs/metrics.go

@@ -81,6 +81,18 @@ var resSz = promauto.NewHistogramVec(prometheus.HistogramOpts{
 	Buckets: prometheus.ExponentialBuckets(100, 10, 8),
 }, []string{"code", "method", "path"})
 
+var userLookupDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "relay_user_lookup_duration",
+	Help:    "A histogram of user lookup latencies",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})
+
+var newUserDiscoveryDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "relay_new_user_discovery_duration",
+	Help:    "A histogram of new user discovery latencies",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})
+
 // MetricsMiddleware defines handler function for metrics middleware
 func MetricsMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
 	return func(c echo.Context) error {

carstore/bs.go

@@ -645,10 +645,12 @@ func (cs *FileCarStore) writeNewShard(ctx context.Context, root cid.Cid, rev str
 		offset += nw
 	}
 
+	start := time.Now()
 	path, err := cs.writeNewShardFile(ctx, user, seq, buf.Bytes())
 	if err != nil {
 		return nil, fmt.Errorf("failed to write shard file: %w", err)
 	}
+	writeShardFileDuration.Observe(time.Since(start).Seconds())
 
 	shard := CarShard{
 		Root:      models.DbCID{CID: root},
@@ -659,9 +661,11 @@ func (cs *FileCarStore) writeNewShard(ctx context.Context, root cid.Cid, rev str
 		Rev:       rev,
 	}
 
+	start = time.Now()
 	if err := cs.putShard(ctx, &shard, brefs, rmcids, false); err != nil {
 		return nil, err
 	}
+	writeShardMetadataDuration.Observe(time.Since(start).Seconds())
 
 	return buf.Bytes(), nil
 }

carstore/metrics.go

@@ -0,0 +1,18 @@
+package carstore
+
+import (
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/promauto"
+)
+
+var writeShardFileDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "carstore_write_shard_file_duration",
+	Help:    "Duration of writing shard file to disk",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})
+
+var writeShardMetadataDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "carstore_write_shard_metadata_duration",
+	Help:    "Duration of writing shard metadata to DB",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})

did/metrics.go

@@ -9,3 +9,9 @@ var mrResolvedDidsTotal = promauto.NewCounterVec(prometheus.CounterOpts{
 	Name: "multiresolver_resolved_dids_total",
 	Help: "Total number of DIDs resolved",
 }, []string{"resolver"})
+
+var mrResolveDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
+	Name:    "indigo_multiresolver_resolve_duration_seconds",
+	Help:    "A histogram of resolve latencies",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+}, []string{"resolver"})

did/multi.go

@@ -3,6 +3,7 @@ package did
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/whyrusleeping/go-did"
 )
@@ -43,12 +44,17 @@ func (mr *MultiResolver) FlushCacheFor(didstr string) {
 }
 
 func (mr *MultiResolver) GetDocument(ctx context.Context, didstr string) (*did.Document, error) {
+	s := time.Now()
+
 	pdid, err := did.ParseDID(didstr)
 	if err != nil {
 		return nil, err
 	}
 
 	method := pdid.Protocol()
+	defer func() {
+		mrResolveDuration.WithLabelValues(method).Observe(time.Since(s).Seconds())
+	}()
 
 	res, ok := mr.handlers[method]
 	if !ok {

repomgr/metrics.go

@@ -9,3 +9,21 @@ var repoOpsImported = promauto.NewCounter(prometheus.CounterOpts{
 	Name: "repomgr_repo_ops_imported",
 	Help: "Number of repo ops imported",
 })
+
+var openAndSigCheckDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "repomgr_open_and_sig_check_duration",
+	Help:    "Duration of opening and signature check",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})
+
+var calcDiffDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "repomgr_calc_diff_duration",
+	Help:    "Duration of calculating diff",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})
+
+var writeCarSliceDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	Name:    "repomgr_write_car_slice_duration",
+	Help:    "Duration of writing car slice",
+	Buckets: prometheus.ExponentialBuckets(0.001, 2, 15),
+})

repomgr/repomgr.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"strings"
 	"sync"
+	"time"
 
 	atproto "github.com/bluesky-social/indigo/api/atproto"
 	bsky "github.com/bluesky-social/indigo/api/bsky"
@@ -538,6 +539,7 @@ func (rm *RepoManager) HandleExternalUserEvent(ctx context.Context, pdsid uint,
 	unlock := rm.lockUser(ctx, uid)
 	defer unlock()
 
+	start := time.Now()
 	root, ds, err := rm.cs.ImportSlice(ctx, uid, since, carslice)
 	if err != nil {
 		return fmt.Errorf("importing external carslice: %w", err)
@@ -551,6 +553,7 @@ func (rm *RepoManager) HandleExternalUserEvent(ctx context.Context, pdsid uint,
 	if err := rm.CheckRepoSig(ctx, r, did); err != nil {
 		return err
 	}
+	openAndSigCheckDuration.Observe(time.Since(start).Seconds())
 
 	var skipcids map[cid.Cid]bool
 	if ds.BaseCid().Defined() {
@@ -571,10 +574,11 @@ func (rm *RepoManager) HandleExternalUserEvent(ctx context.Context, pdsid uint,
 		}
 	}
 
+	start = time.Now()
 	if err := ds.CalcDiff(ctx, skipcids); err != nil {
 		return fmt.Errorf("failed while calculating mst diff (since=%v): %w", since, err)
-
 	}
+	calcDiffDuration.Observe(time.Since(start).Seconds())
 
 	evtops := make([]RepoOp, 0, len(ops))
 
@@ -631,10 +635,12 @@ func (rm *RepoManager) HandleExternalUserEvent(ctx context.Context, pdsid uint,
 		}
 	}
 
+	start = time.Now()
 	rslice, err := ds.CloseWithRoot(ctx, root, nrev)
 	if err != nil {
 		return fmt.Errorf("close with root: %w", err)
 	}
+	writeCarSliceDuration.Observe(time.Since(start).Seconds())
 
 	if rm.events != nil {
 		rm.events(ctx, &RepoEvent{