Reduce frequency of UpdateChannelsTeam() calls
hloeung opened this issue · 7 comments
hloeung commented
Hi,
On working on the channels pagination, I noticed there are quite a few calls to UpdateChannelsTeam(), some sequentially after another. With pagination in place, this increases the requests and load to the MM server.
For with this patch:
--- a/vendor/github.com/matterbridge/matterclient/channels.go
+++ b/vendor/github.com/matterbridge/matterclient/channels.go
@@ -229,6 +229,7 @@ func (m *Client) UpdateChannelsTeam(teamID string) error {
var moreChannels []*model.Channel
+ m.logger.Errorf("HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go")
for {
mmchannels, resp, err = m.Client.GetPublicChannelsForTeam(teamID, idx, max, "")
if err == nil {
With the patch above and Debug, I'm seeing logging like this:
[2022-11-06T08:30:22+11:00] DEBUG matterclient: WsReceiver response: &model.WebSocketResponse{Status:"OK", SeqReply:5, Data:map[string]interface {}{"node_id":"", "server_time":1.667683822499e+12, "text":"pong", "version":"6.6.0"}, Error:(*model.AppError)(nil)}
[2022-11-06T08:30:22+11:00] DEBUG matterclient: getting response: &model.WebSocketResponse{Status:"OK", SeqReply:5, Data:map[string]interface {}{"node_id":"", "server_time":1.667683822499e+12, "text":"pong", "version":"6.6.0"}, Error:(*model.AppError)(nil)}
[2022-11-06T08:30:22+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:30:26+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
DEBU[2022-11-06T08:30:28+11:00] Updating channels for &model.WebsocketBroadcast{OmitUsers:map[string]bool(nil), UserId:"m45ssk4t4bfwufbghxnmj89d4a", ChannelId:"", TeamId:"", ContainsSanitizedData:false, ContainsSensitiveData:false, ReliableClusterSend:false}
DEBU[2022-11-06T08:30:28+11:00] in handleWsMessage0
[2022-11-06T08:30:29+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:30:31+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:23+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:26+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
DEBU[2022-11-06T08:33:29+11:00] Updating channels for &model.WebsocketBroadcast{OmitUsers:map[string]bool(nil), UserId:"m45ssk4t4bfwufbghxnmj89d4a", ChannelId:"", TeamId:"", ContainsSanitizedData:false, ContainsSensitiveData:false, ReliableClusterSend:false}
DEBU[2022-11-06T08:33:29+11:00] in handleWsMessage0
[2022-11-06T08:33:29+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:32+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:23+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:26+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
DEBU[2022-11-06T08:33:29+11:00] Updating channels for &model.WebsocketBroadcast{OmitUsers:map[string]bool(nil), UserId:"m45ssk4t4bfwufbghxnmj89d4a", ChannelId:"", TeamId:"", ContainsSanitizedData:false, ContainsSensitiveData:false, ReliableClusterSend:false}
DEBU[2022-11-06T08:33:29+11:00] in handleWsMessage0
[2022-11-06T08:33:29+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:33:32+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
...
DEBU[2022-11-06T08:35:13+11:00] MMUser WsReceiver: &model.WebSocketEvent{event:"channel_viewed", data:map[string]interface {}{"channel_id":"pkn6xmxn37rix85w4uurjpkoqo"}, broadcast:(*model.WebsocketBroadcast)(0xc0004fee00), sequence:16, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[2022-11-06T08:35:13+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:35:13+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:35:16+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:35:17+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
DEBU[2022-11-06T08:35:19+11:00] in handleWsMessage4
It looks like maybe there's a channel/go routine to run this frequently? Does it need to be there now given that we call UpdateChannelsTeam() when it's not found in places?
Also, notice the calls seconds apart? These are then multiplied due to pagination.
hloeung commented
Adding this too, channel_viewed:
[2022-11-06T08:47:30+11:00] DEBUG matterclient: WsReceiver event: &model.WebSocketEvent{event:"channel_viewed", data:map[string]interface {}{"channel_id":"1tq37i8sqfrg7x611gifz8xf9y"}, broadcast:(*model.WebsocketBroadcast)(0xc0004fe4c0), sequence:35, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
DEBU[2022-11-06T08:47:30+11:00] MMUser WsReceiver: &model.WebSocketEvent{event:"channel_viewed", data:map[string]interface {}{"channel_id":"1tq37i8sqfrg7x611gifz8xf9y"}, broadcast:(*model.WebsocketBroadcast)(0xc0004fe4c0), sequence:35, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
TRAC[2022-11-06T08:47:30+11:00] handleWsMessage (*matterclient.Message)(0xc000118690)({
...
})
[2022-11-06T08:47:31+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:47:34+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
DEBU[2022-11-06T08:47:36+11:00] Updating channels for &model.WebsocketBroadcast{OmitUsers:map[string]bool(nil), UserId:"m45ssk4t4bfwufbghxnmj89d4a", ChannelId:"", TeamId:"", ContainsSanitizedData:false, ContainsSensitiveData:false, ReliableClusterSend:false}
DEBU[2022-11-06T08:47:36+11:00] in handleWsMessage0
[2022-11-06T08:47:37+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T08:47:37+11:00] DEBUG matterclient: WsReceiver response: &model.WebSocketResponse{Status:"OK", SeqReply:28, Data:map[string]interface {}{"node_id":"", "server_time":1.667684857597e+12, "text":"pong", "version":"6.6.0"}, Error:(*model.AppError)(nil)}
[2022-11-06T08:47:37+11:00] DEBUG matterclient: getting response: &model.WebSocketResponse{Status:"OK", SeqReply:28, Data:map[string]interface {}{"node_id":"", "server_time":1.667684857597e+12, "text":"pong", "version":"6.6.0"}, Error:(*model.AppError)(nil)}
[2022-11-06T08:47:40+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
hloeung commented
Maybe it's a bug in this bit in checkWsActionMessage() in bridge/mattermost6/mattermost.go?
if m.GetChannelName(rmsg.GetBroadcast().ChannelId) != "" {
return
}
hloeung commented
Oh, that's the channel I use for antiIdle. So somehow channelID is empty in the broadcast msg:
TRAC[2022-11-06T08:58:22+11:00] handleWsMessage (*matterclient.Message)(0xc0001129a0)({
Raw: (*model.WebSocketEvent)(0xc000bc9b30)({
event: (string) (len=14) "channel_viewed",
data: (map[string]interface {}) (len=1) {
(string) (len=10) "channel_id": (string) (len=26) "1tq37i8sqfrg7x611gifz8xf9y"
},
broadcast: (*model.WebsocketBroadcast)(0xc0017d2b00)({
OmitUsers: (map[string]bool) <nil>,
UserId: (string) (len=26) "m45ssk4t4bfwufbghxnmj89d4a",
ChannelId: (string) "",
TeamId: (string) "",
ContainsSanitizedData: (bool) false,
ContainsSensitiveData: (bool) false,
ReliableClusterSend: (bool) false
}),
sequence: (int64) 45,
precomputedJSON: (*model.precomputedWebSocketEventJSON)(<nil>)
}),
Post: (*model.Post)(<nil>),
Team: (string) (len=9) "canonical",
Channel: (string) "",
Username: (string) "",
Text: (string) "",
Type: (string) "",
UserID: (string) ""
})
TRAC[2022-11-06T08:58:22+11:00] eventchan (*bridge.Event)(0xc000cc2cc0)({
Type: (string) (len=13) "status_change",
Data: (*bridge.StatusChangeEvent)(0xc000cc2ca0)({
UserID: (string) (len=26) "m45ssk4t4bfwufbghxnmj89d4a",
Status: (string) (len=7) "offline"
})
}) module=matterircd
hloeung commented
#493 reduces the calls. There is still the issue where it's called multiple times in sequence ~4 secs apart:
[2022-11-06T09:40:35+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T09:40:38+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
[2022-11-06T09:40:41+11:00] ERROR matterclient: HAW UpdateChannelsTeam() vendor/github.com/matterbridge/matterclient/channels.go
hloeung commented
Related PR matterbridge/matterclient#2 reduces the subsequent calls to UpdateChannelsTeam()
hloeung commented
Finally got the last of it, UpdateChannels() is only called once on init then only when channel or user changes (that's additions and deletions/archiving).
42wim commented
Thanks for the debug job :)