diff --git a/clientapi/routing/sendevent.go b/clientapi/routing/sendevent.go index bfb48f3d..204d2592 100644 --- a/clientapi/routing/sendevent.go +++ b/clientapi/routing/sendevent.go @@ -17,6 +17,7 @@ package routing import ( "net/http" "sync" + "time" "github.com/matrix-org/dendrite/clientapi/httputil" "github.com/matrix-org/dendrite/clientapi/jsonerror" @@ -27,6 +28,7 @@ import ( userapi "github.com/matrix-org/dendrite/userapi/api" "github.com/matrix-org/gomatrixserverlib" "github.com/matrix-org/util" + "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" ) @@ -40,6 +42,25 @@ var ( userRoomSendMutexes sync.Map // (roomID+userID) -> mutex. mutexes to ensure correct ordering of sendEvents ) +func init() { + prometheus.MustRegister(sendEventDuration) +} + +var sendEventDuration = prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Namespace: "dendrite", + Subsystem: "clientapi", + Name: "sendevent_duration_millis", + Help: "How long it takes to build and submit a new event from the client API to the roomserver", + Buckets: []float64{ // milliseconds + 5, 10, 25, 50, 75, 100, 250, 500, + 1000, 2000, 3000, 4000, 5000, 6000, + 7000, 8000, 9000, 10000, 15000, 20000, + }, + }, + []string{"action"}, +) + // SendEvent implements: // /rooms/{roomID}/send/{eventType} // /rooms/{roomID}/send/{eventType}/{txnID} @@ -75,10 +96,12 @@ func SendEvent( mutex.(*sync.Mutex).Lock() defer mutex.(*sync.Mutex).Unlock() + startedGeneratingEvent := time.Now() e, resErr := generateSendEvent(req, device, roomID, eventType, stateKey, cfg, rsAPI) if resErr != nil { return *resErr } + timeToGenerateEvent := time.Since(startedGeneratingEvent) var txnAndSessionID *api.TransactionID if txnID != nil { @@ -90,6 +113,7 @@ func SendEvent( // pass the new event to the roomserver and receive the correct event ID // event ID in case of duplicate transaction is discarded + startedSubmittingEvent := time.Now() if err := api.SendEvents( req.Context(), rsAPI, api.KindNew, @@ -102,6 +126,7 @@ func SendEvent( util.GetLogger(req.Context()).WithError(err).Error("SendEvents failed") return jsonerror.InternalServerError() } + timeToSubmitEvent := time.Since(startedSubmittingEvent) util.GetLogger(req.Context()).WithFields(logrus.Fields{ "event_id": e.EventID(), "room_id": roomID, @@ -117,6 +142,11 @@ func SendEvent( txnCache.AddTransaction(device.AccessToken, *txnID, &res) } + // Take a note of how long it took to generate the event vs submit + // it to the roomserver. + sendEventDuration.With(prometheus.Labels{"action": "build"}).Observe(float64(timeToGenerateEvent.Milliseconds())) + sendEventDuration.With(prometheus.Labels{"action": "submit"}).Observe(float64(timeToSubmitEvent.Milliseconds())) + return res }