Changing displayname is catastrophically slow. (SYN-311)

[matrixbot]

It takes roughly 70s for me to change my displayname, and 100% cpu on matrix.org.

(Imported from https://matrix.org/jira/browse/SYN-311)

(Reported by @ara4n)

[matrixbot]

Jira watchers: @erikjohnston @leonerd @NegativeMjark @ara4n

[matrixbot]

Kodo did this ~10 times in a row, each one taking ~180s despite him being in only a handful of channels, and took out matrix.org.

We need to fix this, and do dup suppression on the requests to avoid them stacking up and DoSing the world.

-- @ara4n

[matrixbot]

By @​kegan:matrix.org: this is a design problem. We need to send an event in every room, we cant get around that. We could maybe draw it out over time so it doesnt block other requests though.

-- NEB (Bot)

[matrixbot]

I think this is because updating the display name causes synapse to emit join events for every room the user is in. Whenever synapse emits a join event in a room it broadcasts the presence to every remote server in the room. I think sending the presence per remote server per room is what is causing some of the problems.

Hopefully this will be improved by #410

-- @NegativeMjark

[matrixbot]

[~markjh]: Was this improved?

Longer term I would like to separate out profile information from joins, and potentially other things to make this nicer.

-- @erikjohnston

[matrixbot]

I'd also be interested to see if this issue was improved by my recent fix to the way server key handling happens - the bugfix where it requeried every remote server every time...

-- @leonerd

[deepbluev7]

I'd say this is still an issue. For example running Nhekos unit tests, if you run them twice on the same docker container, the display name changes (and avatar changes) are atrociously slow. The second run usually means, that you have 20 to 40 rooms already (didn't count them exactly). This results in the following runtimes:

[==========] Running 37 tests from 2 test suites.
[----------] Global test environment set-up.
[----------] 35 tests from ClientAPI
[ RUN      ] ClientAPI.Register
[       OK ] ClientAPI.Register (400 ms)
[ RUN      ] ClientAPI.LoginSuccess
[       OK ] ClientAPI.LoginSuccess (565 ms)
[ RUN      ] ClientAPI.LoginWrongPassword
[       OK ] ClientAPI.LoginWrongPassword (242 ms)
[ RUN      ] ClientAPI.LoginWrongUsername
[       OK ] ClientAPI.LoginWrongUsername (13 ms)
[ RUN      ] ClientAPI.LoginFlows
[       OK ] ClientAPI.LoginFlows (10 ms)
[ RUN      ] ClientAPI.SSORedirect
[       OK ] ClientAPI.SSORedirect (1 ms)
[ RUN      ] ClientAPI.EmptyUserAvatar
[       OK ] ClientAPI.EmptyUserAvatar (48359 ms)
[ RUN      ] ClientAPI.RealUserAvatar
[       OK ] ClientAPI.RealUserAvatar (47640 ms)
[ RUN      ] ClientAPI.ChangeDisplayName
[       OK ] ClientAPI.ChangeDisplayName (48443 ms)
[ RUN      ] ClientAPI.EmptyDisplayName
[       OK ] ClientAPI.EmptyDisplayName (49116 ms)
[ RUN      ] ClientAPI.CreateRoom
[       OK ] ClientAPI.CreateRoom (2431 ms)
[ RUN      ] ClientAPI.TagRoom
[       OK ] ClientAPI.TagRoom (3045 ms)
[ RUN      ] ClientAPI.LogoutSuccess
[       OK ] ClientAPI.LogoutSuccess (2509 ms)
[ RUN      ] ClientAPI.LogoutInvalidatesTokenOnServer
[       OK ] ClientAPI.LogoutInvalidatesTokenOnServer (2937 ms)
[ RUN      ] ClientAPI.CreateRoomInvites
[       OK ] ClientAPI.CreateRoomInvites (3321 ms)
[ RUN      ] ClientAPI.JoinRoom
[       OK ] ClientAPI.JoinRoom (4020 ms)
[ RUN      ] ClientAPI.LeaveRoom
[       OK ] ClientAPI.LeaveRoom (3535 ms)

Note that this is all running on localhost. There is no reason, why a displayname chnage should take 40s. This has nothing to do with remote traffic. But joining and leaving rooms also takes multiple seconds already, which is not really acceptable as well imo, but it isn't as bad as setting the displayname.

[erikjohnston]

Yup, we're aware of this. For context: changing display names require sending a join event into each joined room for a user, joins are fairly heavy weight and so yeah changing display names takes ages.

[deepbluev7]

Yeah, I kinda just wanted to update the status, since the last comment mentioned this potentially being fixed. I'm aware that joins are expensive and that changing the displayname means sending multiple joins. But that our displayname tests take up 80% of our automated test runtime is somewhat horrible. But I think I heard someone was working on optimizing joins, although that seemed to be focused on federation. Imo if one could optimize joins so that at least in local rooms they take a few hundred ms instead of a few seconds, that would improve the displayname change time by enough already. Not sure, if that is doable in synapse currently without a lot of effort though. If someone figures something like that out, that would be very much appreciated though! :3

[erikjohnston]

That is far from ideal. I am slightly surprised that it is taking quite so long TBH, are they big rooms? Are you using postgres? I wonder if something is getting blocked on the DB, maybe the maximum sb connection count config in synapse needs to be updated?

[deepbluev7]

No, that's just local unit tests with rooms having only a few events. So that is a local docker container using sqlite for convenience. Rooms have 1 to 3 members. I'm guessing sqlite is indeed the bottleneck there, but still: I'm just creating a few rooms for unit tests. They are not complex and entirely local, I'd still expect everything to only take a few seconds, if it is completely local and entirely in cache.

[erikjohnston]

Hmm, maybe its just that we're doing one query at a time with SQLite and docker is adding some overhead. Have you tried using an in-memory database? TBH if you're in docker it might be worth trying throwing up a temporary postgres.

[deepbluev7]

Those two suggestions sound like something, that I should try out. I'll see, if I can do that in the near future and report back.

[bmarty]

User experience is highly impacted, see #11679 for more details. #11679 also contains some lead to try to fix this issue.

[novocaine]

This is happening every time I change my display name on matrix.org for the last couple of weeks, whereas previously it didn't. Has something changed?

[ara4n]

I just changed my displayname and it took ~30 mins for my next incremental sync to return. I dread to think what it did to synapse meanwhile.

[bmarty]

It's also worth noting that sometimes it fails to update my display name in all my rooms. My new name is "benoit", but on Element Android room I am still "benoit - away":

Same thing on element Android

Performing an initial sync do not fix the problem. The room state is definitly wrong. I have to change again my name twice to fix that.

[bmarty]

Another annoying side effect, changing the main display name also reset (when it's working) every custom display names which may have been set using /myroomnick

Maybe the homeserver should not update room membership display name of a room from "A" to "B" when the display name in this room is "C"

[DMRobertson]

matrix-org/matrix-spec#829 covers the fact that this needs a protocol-level change to scale better.

(I'd also really like profiles changes to not contribute new membership events: those end up in auth chains and contribute to the vast amount of data needed to join large rooms.)

[deepbluev7]

Well, there is quite a lot synapse could do to make this appear faster to users. Update the profile and recent rooms first, then do the remaining rooms in the background. That would make it appear almost instant to users.