From 232aef016c928fddd57ac84ff1c9827db4eb68df Mon Sep 17 00:00:00 2001 From: Till <2353100+S7evinK@users.noreply.github.com> Date: Mon, 13 Mar 2023 16:45:14 +0100 Subject: Add basic runtime tracing (#2996) This allows us in almost all places to use regions to further trace down long running tasks. Also removes an unused function. --- roomserver/internal/input/input_events.go | 17 ++++----- roomserver/internal/input/input_latest_events.go | 14 +++---- roomserver/internal/input/input_membership.go | 9 +++-- roomserver/internal/input/input_missing.go | 48 ++++++++++++------------ 4 files changed, 44 insertions(+), 44 deletions(-) (limited to 'roomserver/internal') diff --git a/roomserver/internal/input/input_events.go b/roomserver/internal/input/input_events.go index d709541b..7c7a902f 100644 --- a/roomserver/internal/input/input_events.go +++ b/roomserver/internal/input/input_events.go @@ -28,7 +28,6 @@ import ( "github.com/matrix-org/gomatrixserverlib" "github.com/matrix-org/util" - "github.com/opentracing/opentracing-go" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" @@ -85,10 +84,10 @@ func (r *Inputer) processRoomEvent( default: } - span, ctx := opentracing.StartSpanFromContext(ctx, "processRoomEvent") - span.SetTag("room_id", input.Event.RoomID()) - span.SetTag("event_id", input.Event.EventID()) - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "processRoomEvent") + trace.SetTag("room_id", input.Event.RoomID()) + trace.SetTag("event_id", input.Event.EventID()) + defer trace.EndRegion() // Measure how long it takes to process this event. started := time.Now() @@ -608,8 +607,8 @@ func (r *Inputer) fetchAuthEvents( known map[string]*types.Event, servers []gomatrixserverlib.ServerName, ) error { - span, ctx := opentracing.StartSpanFromContext(ctx, "fetchAuthEvents") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "fetchAuthEvents") + defer trace.EndRegion() unknown := map[string]struct{}{} authEventIDs := event.AuthEventIDs() @@ -753,8 +752,8 @@ func (r *Inputer) calculateAndSetState( event *gomatrixserverlib.Event, isRejected bool, ) error { - span, ctx := opentracing.StartSpanFromContext(ctx, "calculateAndSetState") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "calculateAndSetState") + defer trace.EndRegion() var succeeded bool updater, err := r.DB.GetRoomUpdater(ctx, roomInfo) diff --git a/roomserver/internal/input/input_latest_events.go b/roomserver/internal/input/input_latest_events.go index a223820e..09db1843 100644 --- a/roomserver/internal/input/input_latest_events.go +++ b/roomserver/internal/input/input_latest_events.go @@ -23,9 +23,9 @@ import ( "github.com/getsentry/sentry-go" "github.com/matrix-org/gomatrixserverlib" "github.com/matrix-org/util" - "github.com/opentracing/opentracing-go" "github.com/sirupsen/logrus" + "github.com/matrix-org/dendrite/internal" "github.com/matrix-org/dendrite/internal/sqlutil" "github.com/matrix-org/dendrite/roomserver/api" "github.com/matrix-org/dendrite/roomserver/state" @@ -59,8 +59,8 @@ func (r *Inputer) updateLatestEvents( rewritesState bool, historyVisibility gomatrixserverlib.HistoryVisibility, ) (err error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "updateLatestEvents") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "updateLatestEvents") + defer trace.EndRegion() var succeeded bool updater, err := r.DB.GetRoomUpdater(ctx, roomInfo) @@ -209,8 +209,8 @@ func (u *latestEventsUpdater) doUpdateLatestEvents() error { } func (u *latestEventsUpdater) latestState() error { - span, ctx := opentracing.StartSpanFromContext(u.ctx, "processEventWithMissingState") - defer span.Finish() + trace, ctx := internal.StartRegion(u.ctx, "processEventWithMissingState") + defer trace.EndRegion() var err error roomState := state.NewStateResolution(u.updater, u.roomInfo) @@ -329,8 +329,8 @@ func (u *latestEventsUpdater) calculateLatest( newEvent *gomatrixserverlib.Event, newStateAndRef types.StateAtEventAndReference, ) (bool, error) { - span, _ := opentracing.StartSpanFromContext(u.ctx, "calculateLatest") - defer span.Finish() + trace, _ := internal.StartRegion(u.ctx, "calculateLatest") + defer trace.EndRegion() // First of all, get a list of all of the events in our current // set of forward extremities. diff --git a/roomserver/internal/input/input_membership.go b/roomserver/internal/input/input_membership.go index e1dfa6cf..4028f0b5 100644 --- a/roomserver/internal/input/input_membership.go +++ b/roomserver/internal/input/input_membership.go @@ -18,13 +18,14 @@ import ( "context" "fmt" + "github.com/matrix-org/gomatrixserverlib" + + "github.com/matrix-org/dendrite/internal" "github.com/matrix-org/dendrite/roomserver/api" "github.com/matrix-org/dendrite/roomserver/internal/helpers" "github.com/matrix-org/dendrite/roomserver/storage/shared" "github.com/matrix-org/dendrite/roomserver/storage/tables" "github.com/matrix-org/dendrite/roomserver/types" - "github.com/matrix-org/gomatrixserverlib" - "github.com/opentracing/opentracing-go" ) // updateMembership updates the current membership and the invites for each @@ -36,8 +37,8 @@ func (r *Inputer) updateMemberships( updater *shared.RoomUpdater, removed, added []types.StateEntry, ) ([]api.OutputEvent, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "updateMemberships") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "updateMemberships") + defer trace.EndRegion() changes := membershipChanges(removed, added) var eventNIDs []types.EventNID diff --git a/roomserver/internal/input/input_missing.go b/roomserver/internal/input/input_missing.go index 9627f15a..daef957f 100644 --- a/roomserver/internal/input/input_missing.go +++ b/roomserver/internal/input/input_missing.go @@ -7,16 +7,16 @@ import ( "sync" "time" + "github.com/matrix-org/gomatrixserverlib" + "github.com/matrix-org/util" + "github.com/sirupsen/logrus" + fedapi "github.com/matrix-org/dendrite/federationapi/api" "github.com/matrix-org/dendrite/internal" "github.com/matrix-org/dendrite/roomserver/api" "github.com/matrix-org/dendrite/roomserver/state" "github.com/matrix-org/dendrite/roomserver/storage" "github.com/matrix-org/dendrite/roomserver/types" - "github.com/matrix-org/gomatrixserverlib" - "github.com/matrix-org/util" - "github.com/opentracing/opentracing-go" - "github.com/sirupsen/logrus" ) type parsedRespState struct { @@ -62,8 +62,8 @@ type missingStateReq struct { func (t *missingStateReq) processEventWithMissingState( ctx context.Context, e *gomatrixserverlib.Event, roomVersion gomatrixserverlib.RoomVersion, ) (*parsedRespState, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "processEventWithMissingState") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "processEventWithMissingState") + defer trace.EndRegion() // We are missing the previous events for this events. // This means that there is a gap in our view of the history of the @@ -241,8 +241,8 @@ func (t *missingStateReq) processEventWithMissingState( } func (t *missingStateReq) lookupResolvedStateBeforeEvent(ctx context.Context, e *gomatrixserverlib.Event, roomVersion gomatrixserverlib.RoomVersion) (*parsedRespState, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupResolvedStateBeforeEvent") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupResolvedStateBeforeEvent") + defer trace.EndRegion() type respState struct { // A snapshot is considered trustworthy if it came from our own roomserver. @@ -319,8 +319,8 @@ func (t *missingStateReq) lookupResolvedStateBeforeEvent(ctx context.Context, e // lookupStateAfterEvent returns the room state after `eventID`, which is the state before eventID with the state of `eventID` (if it's a state event) // added into the mix. func (t *missingStateReq) lookupStateAfterEvent(ctx context.Context, roomVersion gomatrixserverlib.RoomVersion, roomID, eventID string) (*parsedRespState, bool, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupStateAfterEvent") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupStateAfterEvent") + defer trace.EndRegion() // try doing all this locally before we resort to querying federation respState := t.lookupStateAfterEventLocally(ctx, eventID) @@ -376,8 +376,8 @@ func (t *missingStateReq) cacheAndReturn(ev *gomatrixserverlib.Event) *gomatrixs } func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, eventID string) *parsedRespState { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupStateAfterEventLocally") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupStateAfterEventLocally") + defer trace.EndRegion() var res parsedRespState roomState := state.NewStateResolution(t.db, t.roomInfo) @@ -449,16 +449,16 @@ func (t *missingStateReq) lookupStateAfterEventLocally(ctx context.Context, even // the server supports. func (t *missingStateReq) lookupStateBeforeEvent(ctx context.Context, roomVersion gomatrixserverlib.RoomVersion, roomID, eventID string) ( *parsedRespState, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupStateBeforeEvent") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupStateBeforeEvent") + defer trace.EndRegion() // Attempt to fetch the missing state using /state_ids and /events return t.lookupMissingStateViaStateIDs(ctx, roomID, eventID, roomVersion) } func (t *missingStateReq) resolveStatesAndCheck(ctx context.Context, roomVersion gomatrixserverlib.RoomVersion, states []*parsedRespState, backwardsExtremity *gomatrixserverlib.Event) (*parsedRespState, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "resolveStatesAndCheck") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "resolveStatesAndCheck") + defer trace.EndRegion() var authEventList []*gomatrixserverlib.Event var stateEventList []*gomatrixserverlib.Event @@ -503,8 +503,8 @@ retryAllowedState: // get missing events for `e`. If `isGapFilled`=true then `newEvents` contains all the events to inject, // without `e`. If `isGapFilled=false` then `newEvents` contains the response to /get_missing_events func (t *missingStateReq) getMissingEvents(ctx context.Context, e *gomatrixserverlib.Event, roomVersion gomatrixserverlib.RoomVersion) (newEvents []*gomatrixserverlib.Event, isGapFilled, prevStateKnown bool, err error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "getMissingEvents") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "getMissingEvents") + defer trace.EndRegion() logger := t.log.WithField("event_id", e.EventID()).WithField("room_id", e.RoomID()) latest, _, _, err := t.db.LatestEventIDs(ctx, t.roomInfo.RoomNID) @@ -633,8 +633,8 @@ func (t *missingStateReq) isPrevStateKnown(ctx context.Context, e *gomatrixserve func (t *missingStateReq) lookupMissingStateViaState( ctx context.Context, roomID, eventID string, roomVersion gomatrixserverlib.RoomVersion, ) (respState *parsedRespState, err error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupMissingStateViaState") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupMissingStateViaState") + defer trace.EndRegion() state, err := t.federation.LookupState(ctx, t.virtualHost, t.origin, roomID, eventID, roomVersion) if err != nil { @@ -665,8 +665,8 @@ func (t *missingStateReq) lookupMissingStateViaState( func (t *missingStateReq) lookupMissingStateViaStateIDs(ctx context.Context, roomID, eventID string, roomVersion gomatrixserverlib.RoomVersion) ( *parsedRespState, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupMissingStateViaStateIDs") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupMissingStateViaStateIDs") + defer trace.EndRegion() t.log.Infof("lookupMissingStateViaStateIDs %s", eventID) // fetch the state event IDs at the time of the event @@ -839,8 +839,8 @@ func (t *missingStateReq) createRespStateFromStateIDs( } func (t *missingStateReq) lookupEvent(ctx context.Context, roomVersion gomatrixserverlib.RoomVersion, _, missingEventID string, localFirst bool) (*gomatrixserverlib.Event, error) { - span, ctx := opentracing.StartSpanFromContext(ctx, "lookupEvent") - defer span.Finish() + trace, ctx := internal.StartRegion(ctx, "lookupEvent") + defer trace.EndRegion() if localFirst { // fetch from the roomserver -- cgit v1.2.3