Slow loading of chat messages

[starypatyk]

I have noticed that sometimes it takes a long time (over two seconds) to open the conversation - i.e. from tapping on the conversation to seeing the chat messages. This happens even in perfect network conditions and is long enough to become annoying.

From the log it seems that most of the time is spent server side in the pullChatMessages API call.

07-15 23:10:43.111 3368 3368 D ChatController: init ChatController: 129977001
07-15 23:10:43.182 3368 3368 D ChatController: onViewBound: 129977001
07-15 23:10:43.185 3368 3368 D ChatController: getRoomInfo - getRoom - calling: 9476779063377071
07-15 23:10:43.354 3368 3368 D ChatController: getRoomInfo - getRoom - got response: 9476779063377071
07-15 23:10:43.370 3368 3368 D ChatController: joinRoomWithPassword - joinRoom - calling: 9476779247796342
07-15 23:10:43.530 3368 3368 D ChatController: joinRoomWithPassword - joinRoom - got response: 9476779247796342
07-15 23:10:43.533 3368 3368 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture <= 0] - calling
07-15 23:10:45.252 3368 3368 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture <= 0] - got response
07-15 23:10:45.256 3368 3368 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture > 0] - calling

I have already started to dig deeper (i.e. in the server side code) and plan to document my findings here (in this issue).

• The first issue that I have noticed is this one: Large number of DB queries during execution of a single API call (nextcloud/server). I am not sure yet, if this is the one that introduces the majority of the delay. However since this causes so many DB requests, I need to get rid of it first before further analysis.
• I have noticed that files (usually images) shared in the chat contribute significantly to the time required to process the API call. See more details in: Reduce number of queries required to read shares. This gives a small improvement on its own, and opens potential for future optimizations (likely in the Files application).
• @nickvergessen implemented an additional improvement for the case when there many shared files in the chat: Delay getting the node until we know that we use the data.
• @nickvergessen also proposed an additional change Use LazyUser when creating the user folder, apparently to be merged real-soon-now.

[starypatyk]

With the work-around that I have applied in my installation, the time spent in the pullChatMessages API call in my environment has decreased significantly - from around 1.7 s to 0.6 s.

07-25 00:13:31.581 14588 14588 D ChatController: init ChatController: 35895317
07-25 00:13:31.712 14588 14588 D ChatController: onViewBound: 35895317
07-25 00:13:31.722 14588 14588 D ChatController: getRoomInfo - getRoom - calling: 9663376222315524
07-25 00:13:31.887 14588 14588 D ChatController: getRoomInfo - getRoom - got response: 9663376222315524
07-25 00:13:31.902 14588 14588 D ChatController: joinRoomWithPassword start: false sessionId: 0
07-25 00:13:31.903 14588 14588 D ChatController: joinRoomWithPassword - joinRoom - calling: 9663376402784483
07-25 00:13:32.055 14588 14588 D ChatController: joinRoomWithPassword - joinRoom - got response: 9663376402784483
07-25 00:13:32.057 14588 14588 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture <= 0] - calling
07-25 00:13:32.638 14588 14588 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture <= 0] - got response
07-25 00:13:32.656 14588 14588 D ChatController: pullChatMessages - pullChatMessages[lookIntoFuture > 0] - calling

It is still TBD if the issue that I had (Large number of DB queries during execution of a single API call) is a common problem or just something incorrect in my installation. Seems to be a problem with database upgrade (migration), but this needs to be confirmed.

I plan to keep digging. 😉

[starypatyk]

I have noticed that files (usually images) shared in the chat contribute significantly to the time required to process the API call. See more details in: Reduce number of queries required to read shares. This gives a small improvement on its own, and opens potential for future optimizations (likely in the Files application).

[starypatyk]

With nextcloud/server#33540, nextcloud/spreed#7743, nextcloud/spreed#7762 already merged and nextcloud/server#33578 to be merged soon, I think we are getting to the point of diminishing returns.

Preliminary measurements on my "production" server show a reduction in execution time of the pullChatMessages API call from about 1700 ms to 450 ms (4x faster). And this is even without backporting nextcloud/server#33578.

This is just enough that opening the conversation is no longer annoying. 😉 Still does not feel immediate, but is much better than previously.

I plan to keep this issue open for some time - until I am able to confirm the results on the released 25 version.

[nickvergessen]

I plan to keep this issue open for some time - until I am able to confirm the results on the released 25 version.

I would actually tend to do the opposite. We can close this one as all current ideas have been implemented and 3/4 have been merged. If there is still an issue in 25 we should create a new issue with new profiling of the results and problems in the https://github.com/nextcloud/spreed/ repo.

Also it is kind of needed to close issues once they are fixed in master to be able to maintain an overview across the projects and issue trackers.

[starypatyk]

I would actually tend to do the opposite.

@nickvergessen - fair enough. 😉 Closing.