nextcloud
Slow loading of chat messages
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).
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. :wink:
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).
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. :wink: 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.
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.
I would actually tend to do the opposite.
@nickvergessen - fair enough. :wink: Closing.