Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Slow sync makes mobile apps unusable #7781

Closed
rihardsk opened this issue Jul 3, 2020 · 4 comments
Closed

Slow sync makes mobile apps unusable #7781

rihardsk opened this issue Jul 3, 2020 · 4 comments
Labels
A-Performance Performance, both client-facing and admin-facing A-Sync defects related to /sync z-p2 (Deprecated Label)

Comments

@rihardsk
Copy link

rihardsk commented Jul 3, 2020 •
edited
Loading

Description

Every time i check my messages on my phone with RiotX there's a 5-12 second sync which makes it very inconvenient to use. This happens if all other clients are offline and if i haven't opened the app for longer than a minute or so. If i have riot-desktop open at the time the syncs are barely noticeable (below 1 second).

I'm running a single user HS so when the slow syncs happen RiotX is the only client attempting to connect in a while.

I've noticed the same long syncs when riot-desktop is opened after a period of inactivity. But, although the syncs take about the same amount of time, it's practically a non-issue on desktop because it happens only once and then riot-desktop remains open and everything's fast as expected.

Steps to reproduce

  • disconnect all clients on a homeserver
  • open a client after >1 minutes
  • experience a 5-12 second sync

Logs

Here are some log snippets that illustrate the above.

First sync after a period of inactivity (client is RiotX):

Jul 03 14:59:30 matrix synapse[32346]: synapse.access.http.8008: [GET-1673118] - - 8008 - {@my-username:my-domain.example.com} Processed request: 6.858sec/2.741sec (0.009sec, 0.000sec) (0.000sec/0.000sec/0) 497B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s278661_15982831_22092_669225_7135_10_911_207904_112&filter=4&set_presence=offline HTTP/1.1" "Python/3.8 aiohttp/3.6.2" [0 dbevts]
Jul 03 14:59:36 matrix synapse[32346]: synapse.access.http.8008: [GET-1673135] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 8.936sec/0.019sec (0.167sec, 0.002sec) (0.040sec/0.111sec/10) 58636B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=0&since=s278556_15977307_21558_668681_7135_10_910_207645_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]
Jul 03 14:59:38 matrix synapse[32346]: synapse.access.http.8008: [GET-1673142] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 0.017sec/0.011sec (0.009sec, 0.000sec) (0.000sec/0.000sec/0) 948B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s278661_15982836_22092_669225_7135_10_911_207904_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]
Jul 03 14:59:38 matrix synapse[32346]: synapse.access.http.8008: [GET-1673136] - - 8008 - {@my-username:my-domain.example.com} Processed request: 6.034sec/0.006sec (0.020sec, 0.000sec) (0.004sec/0.004sec/1) 829B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s278661_15982835_22092_669225_7135_10_911_207904_112&filter=4&set_presence=offline HTTP/1.1" "Python/3.8 aiohttp/3.6.2" [0 dbevts]
Jul 03 14:59:38 matrix synapse[32346]: synapse.access.http.8008: [GET-1673147] - - 8008 - {@my-username:my-domain.example.com} Processed request: 0.116sec/0.001sec (0.014sec, 0.000sec) (0.003sec/0.009sec/2) 1885B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s278661_15982837_22092_669230_7135_10_911_207904_112&filter=4&set_presence=offline HTTP/1.1" "Python/3.8 aiohttp/3.6.2" [0 dbevts]
Jul 03 14:59:39 matrix synapse[32346]: synapse.access.http.8008: [GET-1673152] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 1.399sec/0.001sec (0.012sec, 0.000sec) (0.088sec/0.014sec/4) 475B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s278661_15982837_22092_669230_7135_10_911_207904_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]

Sync on RiotX when riot-desktop is also running (both RiotX and riot-desktop requests are here, all are fast):

Jul 03 15:42:11 matrix synapse[32346]: synapse.access.http.8008: [GET-1676677] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 3.185sec/0.007sec (0.005sec, 0.000sec) (0.000sec/0.000sec/0) 476B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985445_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:11 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676679] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985446_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:12 matrix synapse[32346]: synapse.access.http.8008: [GET-1676680] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 0.733sec/0.007sec (0.011sec, 0.000sec) (0.000sec/0.000sec/0) 500B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985446_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:12 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676683] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.004sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985448_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:13 matrix synapse[32346]: synapse.access.http.8008: [GET-1676684] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 1.648sec/0.007sec (0.007sec, 0.000sec) (0.000sec/0.000sec/0) 503B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985448_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:13 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676686] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985449_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:15 matrix synapse[32346]: synapse.access.http.8008: [GET-1676687] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 1.178sec/0.004sec (0.008sec, 0.000sec) (0.000sec/0.000sec/0) 502B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985449_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:15 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676689] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985450_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:16 matrix synapse[32346]: synapse.access.http.8008: [GET-1676691] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 0.086sec/0.001sec (0.049sec, 0.000sec) (0.024sec/0.034sec/7) 49057B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=0&since=s278673_15983636_22129_669296_7135_10_912_207926_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]
Jul 03 15:42:17 matrix synapse[32346]: synapse.access.http.8008: [GET-1676690] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 2.148sec/0.004sec (0.006sec, 0.002sec) (0.000sec/0.000sec/0) 487B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985450_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:17 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676700] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985451_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:18 matrix synapse[32346]: synapse.access.http.8008: [GET-1676706] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 0.007sec/0.001sec (0.008sec, 0.000sec) (0.000sec/0.000sec/0) 487B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s278681_15985450_22155_669384_7135_10_913_207988_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]
Jul 03 15:42:18 matrix synapse[32346]: synapse.access.http.8008: [GET-1676709] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 0.453sec/0.012sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 511B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s278681_15985451_22155_669384_7135_10_913_207988_112 HTTP/1.0" "RiotX/0.22.0 (Linux; U; Android 9; MY PHONE Build/PKQ1.181203.00; Flavour GooglePlay; MatrixAndroidSDK_X 0.0.1)" [0 dbevts]
Jul 03 15:42:18 matrix synapse[32346]: synapse.access.http.8008: [GET-1676701] 192.168.1.1 - 8008 - {@my-username:my-domain.example.com} Processed request: 1.647sec/0.009sec (0.008sec, 0.000sec) (0.000sec/0.000sec/0) 511B 200 "GET /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985451_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
Jul 03 15:42:18 matrix synapse[32346]: synapse.access.http.8008: [OPTIONS-1676714] 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "OPTIONS /_matrix/client/r0/sync?filter=5&timeout=30000&since=s278681_15985452_22155_669384_7135_10_913_207988_112 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.6.4 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]

Here are the full logs of around that time
slow-sync-riotx.redacted.log
ok-sync-riot-and-riotx.redacted.log

Version information

  • Homeserver: private homeserver

  • Version: 1.15.1 (issue experienced on multiple previous versions as well)

  • Install method: NixOS

  • Platform: NixOS on ROCKPro64 single board computer
@babolivier babolivier added A-Performance Performance, both client-facing and admin-facing A-Sync defects related to /sync z-p2 (Deprecated Label) labels Jul 7, 2020
@richvdh
Copy link
Member

richvdh commented Jul 9, 2020

possibly related: #3880, though I think it's something different

@rihardsk
Copy link
Author

rihardsk commented Nov 24, 2020 •
edited
Loading

Turned off presence on my homeserver and the issue is completely gone now. So i guess this issue is related to #3971.

I think what might be happening is that, while at least one other device is logged in (and is active), opening the mobile app (or the desktop app) doesn't trigger a presence update and sync responds in a timely manner. However, if no other devices are active at the moment and an app is opened, the homeserver immediately proceeds to send presence updates and that pegs the CPU making sync take a lot longer.

Since discovering the workaround (turning off presence) this no longer bothers me so, as far as I'm concerned, this could be closed, but i guess this could be considered a separate issue from #3971? I'll let the maintainers decide.

@clokep
Copy link
Contributor

clokep commented Nov 24, 2020

Thanks for looking deeper into this. Since it seems fixed with #3971, I agree that it seems to be a duplicate of that!

@clokep clokep closed this as completed Nov 24, 2020
@swordapi
Copy link

This is still a problem.

@billythedummy billythedummy mentioned this issue Feb 20, 2023
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Performance Performance, both client-facing and admin-facing A-Sync defects related to /sync z-p2 (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@clokep @richvdh @rihardsk @babolivier @swordapi