diff --git a/bgs/bgs.go b/bgs/bgs.go index bf1eae6f5..b64df715e 100644 --- a/bgs/bgs.go +++ b/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) } diff --git a/bgs/metrics.go b/bgs/metrics.go index b33677e6e..edd687596 100644 --- a/bgs/metrics.go +++ b/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 { diff --git a/did/metrics.go b/did/metrics.go index e7bea3b56..67f14e434 100644 --- a/did/metrics.go +++ b/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", + Help: "A histogram of resolve latencies", + Buckets: prometheus.ExponentialBuckets(0.001, 2, 15), +}, []string{"resolver"}) diff --git a/did/multi.go b/did/multi.go index e871ff454..112394bee 100644 --- a/did/multi.go +++ b/did/multi.go @@ -3,6 +3,7 @@ package did import ( "context" "fmt" + "time" "github.com/whyrusleeping/go-did" ) @@ -43,6 +44,11 @@ func (mr *MultiResolver) FlushCacheFor(didstr string) { } func (mr *MultiResolver) GetDocument(ctx context.Context, didstr string) (*did.Document, error) { + s := time.Now() + defer func() { + mrResolveDuration.WithLabelValues(didstr).Observe(time.Since(s).Seconds()) + }() + pdid, err := did.ParseDID(didstr) if err != nil { return nil, err diff --git a/repomgr/metrics.go b/repomgr/metrics.go index a92e3091d..df3e4bea1 100644 --- a/repomgr/metrics.go +++ b/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), +}) diff --git a/repomgr/repomgr.go b/repomgr/repomgr.go index ad90a43b2..bdf20d784 100644 --- a/repomgr/repomgr.go +++ b/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{