From ddbfb1bd68326f272dee1a360d15b964e09e564a Mon Sep 17 00:00:00 2001 From: Nick Barrett Date: Wed, 3 Aug 2022 09:08:02 +0100 Subject: [PATCH 1/2] Log duration of AS request handling --- appservice/websocket.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/appservice/websocket.go b/appservice/websocket.go index 393b1ccaa..650089751 100644 --- a/appservice/websocket.go +++ b/appservice/websocket.go @@ -289,9 +289,11 @@ func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn) as.websocketRequestsLock.RUnlock() } else { as.Log.Debugfln("Received command request %s %d", msg.Command, msg.ReqID) + startTime := time.Now() as.websocketHandlersLock.RLock() handler, ok := as.websocketHandlers[msg.Command] as.websocketHandlersLock.RUnlock() + duration := time.Now().Sub(startTime) if !ok { handler = as.unknownCommandHandler } @@ -301,9 +303,9 @@ func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn) if err != nil { as.Log.Warnfln("Failed to send response to %s %d: %v", msg.Command, msg.ReqID, err) } else if okResp { - as.Log.Debugfln("Sent success response to %s %d", msg.Command, msg.ReqID) + as.Log.Debugfln("Sent success response to %s %d (took %s)", msg.Command, msg.ReqID, duration) } else { - as.Log.Debugfln("Sent error response to %s %d", msg.Command, msg.ReqID) + as.Log.Debugfln("Sent error response to %s %d (took %s)", msg.Command, msg.ReqID, duration) } }() } From 46e905fb56fdf7366dc4bdd7d1bffa5485940f02 Mon Sep 17 00:00:00 2001 From: Nick Barrett Date: Wed, 3 Aug 2022 09:33:29 +0100 Subject: [PATCH 2/2] Fix duration log for AS requests --- appservice/websocket.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/appservice/websocket.go b/appservice/websocket.go index 650089751..11564cb05 100644 --- a/appservice/websocket.go +++ b/appservice/websocket.go @@ -289,16 +289,16 @@ func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn) as.websocketRequestsLock.RUnlock() } else { as.Log.Debugfln("Received command request %s %d", msg.Command, msg.ReqID) - startTime := time.Now() as.websocketHandlersLock.RLock() handler, ok := as.websocketHandlers[msg.Command] as.websocketHandlersLock.RUnlock() - duration := time.Now().Sub(startTime) if !ok { handler = as.unknownCommandHandler } go func() { + startTime := time.Now() okResp, data := handler(msg.WebsocketCommand) + duration := time.Now().Sub(startTime) err = as.SendWebsocket(msg.MakeResponse(okResp, data)) if err != nil { as.Log.Warnfln("Failed to send response to %s %d: %v", msg.Command, msg.ReqID, err)