Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Message history loading takes up to 20 sec #21456

Open
mariia-skrypnyk opened this issue Oct 18, 2024 · 10 comments · May be fixed by #21642
Open

Message history loading takes up to 20 sec #21456

mariia-skrypnyk opened this issue Oct 18, 2024 · 10 comments · May be fixed by #21642
Assignees
@qfrank
Labels
mobile-core performance
Milestone
2.32.0

Comments

@mariia-skrypnyk
Copy link

mariia-skrypnyk commented Oct 18, 2024 •
edited
Loading

Bug Report

Follow up of #21411
In this 👆 PR perfomance issue with message loading was already improved but seems that there is a way to make it more faster.

Reproduction

  1. Login to app as a Receiver (a member of Status community)
  2. Login to another device as a Sender (a member of Status community)
  3. As a Receiver do a logout and close the app.
  4. As a Sender wait till Receiver status become offline and send 20+ messages to 1-1 chat with a Receiver.
  5. As a Receiver login and open chat with a Sender.

Expected behavior

Message history loading takes less then 20 sec

Actual behavior

Message history loading takes up to 20 sec

Receiver_1.zip
Sender_1.zip

Additional Information

  • Status version: nightly 18.10
  • Operating System: Android, iOS
@mariia-skrypnyk mariia-skrypnyk mentioned this issue Oct 18, 2024
Merged
@qfrank qfrank self-assigned this Oct 21, 2024
@qfrank
Copy link
Contributor

qfrank commented Oct 21, 2024 •
edited
Loading

Not sure if "wallet_fetchTokenDetails", "wallet_getWalletToken", "wallet_fetchPrices", and "wallet_fetchMarketValues" will affect the delay? Each of them took up around 6 seconds in the requests.log provided by @mariia-skrypnyk . And wakuext_startMessenger only took around 1-2 seconds

@qfrank
Copy link
Contributor

qfrank commented Oct 21, 2024

The following is the requests.log provided by @pavloburykh .

t=2024-10-21T07:20:53+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchPrices\", duration=1.091404166s
t=2024-10-21T07:20:53+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchMarketValues\", duration=1.330106041s

t=2024-10-21T07:20:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=2.265590833s
t=2024-10-21T07:20:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=2.838512759s

t=2024-10-21T07:21:04+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=2.760202916s
t=2024-10-21T07:21:04+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=1.593322291s
t=2024-10-21T07:27:57+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_startMessenger\", duration=1.08818302s

t=2024-10-21T07:28:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=3.145335103s
t=2024-10-21T07:28:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=1.827232239s
t=2024-10-21T07:28:49+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=1.29525276s
t=2024-10-21T07:28:49+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=1.984796978s

t=2024-10-21T07:29:33+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=1.842255156s
t=2024-10-21T07:31:06+0000 lvl=dbug msg=logout params=[] resp="{\"error\":\"\"}" duration=4.199286353s

t=2024-10-21T07:31:09+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_startMessenger\", duration=1.896472708s
t=2024-10-21T07:31:10+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=2.572267916s

t=2024-10-21T07:31:11+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=3.326391249s
t=2024-10-21T07:31:11+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchMarketValues\", duration=1.332989583s
t=2024-10-21T07:31:11+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=1.453261979s
t=2024-10-21T07:31:13+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchPrices\", duration=2.950787968s

t=2024-10-21T07:32:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_startMessenger\", duration=1.063248541s
t=2024-10-21T07:32:58+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=3.770931248s
t=2024-10-21T07:33:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=3.686795155s
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=7.172142237s

@qfrank
Copy link
Contributor

qfrank commented Oct 21, 2024

emm.. after investigating Status.log provided by @pavloburykh , I found there is around 5-6 seconds delay for the signal type messages.new after loginAccount, wallet_xxx should not affect the delay relate to chat UI.

@qfrank
Copy link
Contributor

qfrank commented Oct 21, 2024 •
edited
Loading

emm..

Status.log:

10-21 10:32:53.676  4318  4465 D ReactNativeJS: 2024-10-21T07:32:53.674Z DEBUG [status-im.common.signals.events:34] - Signal received {:type "node.login"}
10-21 10:32:53.681  4318  4465 D ReactNativeJS: 2024-10-21T07:32:53.679Z DEBUG [status-im.contexts.profile.login.events:154] - [signals] node.login error nil

requests.log:

t=2024-10-21T07:32:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_startMessenger\", duration=1.063248541s
...
t=2024-10-21T07:32:59+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_chatsPreview\", duration=409.644271ms

Look at the time. I would expect wakuext_chatsPreview to be invoked soon after receiving signal node.login, but actually it isn't. It gets delayed for around 5-6 seconds. So we should figure out why the delay occurs on the frontend. Could you help take a look? @ilmotta

@qfrank
Copy link
Contributor

qfrank commented Oct 21, 2024

to be clear, I made a short simplified log for requests.log:

t=2024-10-21T07:32:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_startMessenger\", duration=1.063248541s
t=2024-10-21T07:32:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_serializedCommunities\", duration=466.984635ms
t=2024-10-21T07:32:54+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getTokenList\", duration=31.441719ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=6.373854ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=9.569219ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=6.685469ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=5.012917ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=3.768177ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=10.435937ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=12.288177ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=15.324375ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=37.269271ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=43.618281ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=191.189948ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkPermissionsToJoinCommunity\", duration=241.528073ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_checkAndDeletePendingRequestToJoinCommunity\", duration=2.158906ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_collapsedCommunityCategories\", duration=3.047292ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchPrices\", duration=616.622083ms
t=2024-10-21T07:32:56+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchMarketValues\", duration=651.834114ms
t=2024-10-21T07:32:57+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletConnectActiveSessions\", duration=3.035468ms
t=2024-10-21T07:32:58+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=3.770931248s
t=2024-10-21T07:32:58+0000 lvl=dbug msg=serializeLegacyKey params=[0x04170e3288ba51cce14e6d5a9a3b09ab53c9dc35df15c429164d7c57008bd10327e51315d7e41e5cb7299c00215e09c5ae783187a76d82dcbd007b4b9d4b3445b3] resp=zQ3shgC74U8kmFyW3yKGmMsnyfMYM9y6Gj75ZxJpy1SbDcFR8 duration="60.99µs"
t=2024-10-21T07:32:58+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_activityCenterNotificationsCount\", duration=1.310469ms
t=2024-10-21T07:32:58+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_activityCenterNotifications\", duration=2.532968ms
t=2024-10-21T07:32:59+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_chatsPreview\", duration=409.644271ms
t=2024-10-21T07:33:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_fetchTokenDetails\", duration=3.686795155s
t=2024-10-21T07:33:00+0000 lvl=dbug msg=startLocalNotifications params=[] resp="{\"error\":\"\"}" duration="578.437µs"
t=2024-10-21T07:33:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"multiaccounts_getIdentityImages\", duration=1.62448ms
t=2024-10-21T07:33:00+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_myPendingRequestsToJoin\", duration=1.213489ms
t=2024-10-21T07:33:00+0000 lvl=dbug msg=serializeLegacyKey params=[0x04b77894beebf9b63c42608217d9cdd3210e322ebce301b177845c760f0c54f784293144af5a21379de2a5aee8d8cc3c021309fbf664dea61165a446a6b9fba7f0] resp=zQ3shZkz1QfcHHM3HEqs3y7mLtsJG4CV5AP53bKYcsU3Biib5 duration="67.552µs"
t=2024-10-21T07:33:00+0000 lvl=dbug msg=serializeLegacyKey params=[0x047123241193182e748f7e109280294cbfbd2dd43bc0d0b7bad715a17850dff4358b86c8d0b1008f6dd16607d227a1338917e594328762937eacedff9d48b304b9] resp=zQ3shnFkGxWSJGfzEUkQde9V5nEVoYZEMYVJ7MfYhc9XmSNFn duration="113.907µs"
t=2024-10-21T07:33:00+0000 lvl=dbug msg=serializeLegacyKey params=[] resp="{\"error\":\"invalid key length\"}" duration="166.927µs"
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wallet_getWalletToken\", duration=7.172142237s
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_contacts\", duration=176.14927ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_getBrowsers\", duration=2.393541ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"web3_clientVersion\",
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"permissions_getDappPermissions\", duration=2.55276ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"localnotifications_notificationPreferences\", duration=3.479323ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"browsers_getBookmarks\", duration=6.370729ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_activityCenterNotificationsCount\", duration=3.631458ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_getOurInstallations\", duration=4.778854ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"admin_nodeInfo\", duration=1.35474ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_hasUnseenActivityCenterNotifications\", duration=4.507708ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_shareUserURLWithData\", duration=4.4725ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_statusUpdates\", duration=9.835834ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_getGroupChatInvitations\", duration=36.319896ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=getNodeConfig params=[] resp="{\"NetworkId\":1,\"DataDir\":\"/ethereum/mainnet_rpc\",\"KeyStoreDir\":\"keystore/0x9677ba828b37677c5384bfe527df96d80a10f6f9c6f40a1b65c51e22ac3a418b\",\"KeycardPairingDataFile\":\"\",\"NodeKey\":\"\",\"NoDiscovery\":true,\"ListenAddr\":\":0\",\"AdvertiseAddr\":\"\",\"Name\":\"StatusIM\",\"Version\":\"\",\"APIModules\":\"\",\"HTTPEnabled\":false,\"HTTPHost\":\"\",\"HTTPPort\":0,\"WSEnabled\":false,\"WSHost\":\"\",\"WSPort\":0,\"HTTPVirtualHosts\":null,\"HTTPCors\":null,\"IPCEnabled\":false,\"IPCFile\":\"\",\"TLSEnabled\":false,\"MaxPeers\":20,\"MaxPendingPeers\":20,\"LogEnabled\":true,\"LogMobileSystem\":false,\"LogDir\":\"/storage/emulated/0/Android/data/im.status.ethereum.pr/files/Download\",\"LogFile\":\"geth.log\",\"RuntimeLogLevel\":\"\",\"LogLevel\":\"DEBUG\",\"LogMaxBackups\":0,\"LogMaxSize\":0,\"LogCompressRotated\":false,\"LogToStderr\":false,\"EnableStatusService\":false,\"Networks\":[{\"chainId\":1,\"chainName\":\"Mainnet\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://eth-archival.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://etherscan.io/\",\"iconUrl\":\"network/Network=Ethereum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":false,\"layer\":1,\"enabled\":true,\"chainColor\":\"#627EEA\",\"shortName\":\"eth\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":5,\"chainName\":\"Mainnet\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://goerli.infura.io/v3/40ec14d9d9384d52b7fbcfecdde4e2c0\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://goerli.etherscan.io/\",\"iconUrl\":\"network/Network=Ethereum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":1,\"enabled\":true,\"chainColor\":\"#627EEA\",\"shortName\":\"goEth\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":10,\"chainName\":\"Optimism\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://optimism-archival.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://optimistic.etherscan.io\",\"iconUrl\":\"network/Network=Optimism\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":false,\"layer\":2,\"enabled\":true,\"chainColor\":\"#E90101\",\"shortName\":\"oeth\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":420,\"chainName\":\"Optimism\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://optimism-goerli.infura.io/v3/40ec14d9d9384d52b7fbcfecdde4e2c0\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://goerli-optimism.etherscan.io/\",\"iconUrl\":\"network/Network=Optimism\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":2,\"enabled\":false,\"chainColor\":\"#E90101\",\"shortName\":\"goOpt\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":42161,\"chainName\":\"Arbitrum\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://arbitrum-one.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://arbiscan.io/\",\"iconUrl\":\"network/Network=Arbitrum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":false,\"layer\":2,\"enabled\":true,\"chainColor\":\"#51D0F0\",\"shortName\":\"arb1\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":421613,\"chainName\":\"Arbitrum\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://arbitrum-goerli.infura.io/v3/40ec14d9d9384d52b7fbcfecdde4e2c0\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://goerli.arbiscan.io/\",\"iconUrl\":\"network/Network=Arbitrum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":2,\"enabled\":false,\"chainColor\":\"#51D0F0\",\"shortName\":\"goArb\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":421614,\"chainName\":\"Arbitrum\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://arbitrum-sepolia-archival.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://sepolia-explorer.arbitrum.io/\",\"iconUrl\":\"network/Network=Arbitrum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":2,\"enabled\":false,\"chainColor\":\"#51D0F0\",\"shortName\":\"arb1\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":11155111,\"chainName\":\"Mainnet\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://sepolia-archival.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://sepolia.etherscan.io/\",\"iconUrl\":\"network/Network=Ethereum\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":1,\"enabled\":true,\"chainColor\":\"#627EEA\",\"shortName\":\"eth\",\"tokenOverrides\":null,\"relatedChainId\":0},{\"chainId\":11155420,\"chainName\":\"Optimism\",\"defaultRpcUrl\":\"\",\"defaultFallbackURL\":\"\",\"defaultFallbackURL2\":\"\",\"rpcUrl\":\"https://optimism-sepolia-archival.rpc.grove.city/v1/1fec70c0d1247dc818107ac7\",\"originalRpcUrl\":\"\",\"fallbackURL\":\"\",\"originalFallbackURL\":\"\",\"blockExplorerUrl\":\"https://sepolia-optimism.etherscan.io/\",\"iconUrl\":\"network/Network=Optimism\",\"nativeCurrencyName\":\"Ether\",\"nativeCurrencySymbol\":\"ETH\",\"nativeCurrencyDecimals\":18,\"isTest\":true,\"layer\":2,\"enabled\":false,\"chainColor\":\"#E90101\",\"shortName\":\"oeth\",\"tokenOverrides\":null,\"relatedChainId\":0}],\"ClusterConfig\":{\"Enabled\":true,\"Fleet\":\"status.prod\",\"StaticNodes\":null,\"BootNodes\":null,\"TrustedMailServers\":null,\"PushNotificationsServers\":[\"181141b1d111908aaf05f4788e6778ec07073a1d4e1ce43c73815c40ee4e7345a1cbf5a90a45f601bf3763f12be63b01624ba1f36eeb9572455e7034b8f9f2c4\",\"401ba5eda402678dc78a0a40fd0795f4ea8b1e34972c4d15cf33ac01292341c89f0cbc637fa9f7a3ffe0b9dfe90e9cdae7a14925500ab01b6a91c67bae42a97a\",\"5ffc34d5ffda180d94cd3974d9ed2bb082ede68f342babdbe801ceffb7da902087d43f9aa961c7b85029358874c08ef04ecad9f1d95a1f0e448cbdd5d04350c7\"],\"WakuNodes\":[\"enrtree://AMOJVZX4V6EXP7NTJPMAYJYST2QP6AJXYW76IU6VGJS7UVSNDYZG4@boot.prod.status.nodes.status.im\"],\"DiscV5BootstrapNodes\":[\"enr:-QEKuED9AJm2HGgrRpVaJY2nj68ao_QiPeUT43sK-aRM7sMJ6R4G11OSDOwnvVacgN1sTw-K7soC5dzHDFZgZkHU0u-XAYJpZIJ2NIJpcISnYxMvim11bHRpYWRkcnO4WgAqNiVib290LTAxLmRvLWFtczMuc3RhdHVzLnByb2Quc3RhdHVzLmltBnZfACw2JWJvb3QtMDEuZG8tYW1zMy5zdGF0dXMucHJvZC5zdGF0dXMuaW0GAbveA4Jyc40AEAUAAQAgAEAAgAEAiXNlY3AyNTZrMaEC3rRtFQSgc24uWewzXaxTY8hDAHB8sgnxr9k8Rjb5GeSDdGNwgnZfg3VkcIIjKIV3YWt1Mg0\",\"enr:-QEcuEAoShWGyN66wwusE3Ri8hXBaIkoHZHybUB8cCPv5v3ypEf9OCg4cfslJxZFANl90s-jmMOugLUyBx4EfOBNJ6_VAYJpZIJ2NIJpcIQI2hdMim11bHRpYWRkcnO4bAAzNi5ib290LTAxLmFjLWNuLWhvbmdrb25nLWMuc3RhdHVzLnByb2Quc3RhdHVzLmltBnZfADU2LmJvb3QtMDEuYWMtY24taG9uZ2tvbmctYy5zdGF0dXMucHJvZC5zdGF0dXMuaW0GAbveA4Jyc40AEAUAAQAgAEAAgAEAiXNlY3AyNTZrMaEDP7CbRk-YKJwOFFM4Z9ney0GPc7WPJaCwGkpNRyla7mCDdGNwgnZfg3VkcIIjKIV3YWt1Mg0\",\"enr:-QEcuED7ww5vo2rKc1pyBp7fubBUH-8STHEZHo7InjVjLblEVyDGkjdTI9VdqmYQOn95vuQH-Htku17WSTzEufx-Wg4mAYJpZIJ2NIJpcIQihw1Xim11bHRpYWRkcnO4bAAzNi5ib290LTAxLmdjLXVzLWNlbnRyYWwxLWEuc3RhdHVzLnByb2Quc3RhdHVzLmltBnZfADU2LmJvb3QtMDEuZ2MtdXMtY2VudHJhbDEtYS5zdGF0dXMucHJvZC5zdGF0dXMuaW0GAbveA4Jyc40AEAUAAQAgAEAAgAEAiXNlY3AyNTZrMaECxjqgDQ0WyRSOilYU32DA5k_XNlDis3m1VdXkK9xM6kODdGNwgnZfg3VkcIIjKIV3YWt1Mg0\",\"enrtree://AMOJVZX4V6EXP7NTJPMAYJYST2QP6AJXYW76IU6VGJS7UVSNDYZG4@boot.prod.status.nodes.status.im\"],\"ClusterID\":16},\"LightEthConfig\":{\"Enabled\":false,\"DatabaseCache\":0,\"TrustedNodes\":null,\"MinTrustedFraction\":0},\"WakuConfig\":{\"Enabled\":false,\"LightClient\":false,\"FullNode\":false,\"EnableMailServer\":false,\"DataDir\":\"\",\"MinimumPoW\":0,\"MailServerPassword\":\"***\",\"MailServerRateLimit\":0,\"MailServerDataRetention\":0,\"TTL\":0,\"MaxMessageSize\":0,\"DatabaseConfig\":{\"PGConfig\":{\"Enabled\":false,\"URI\":\"\"}},\"EnableRateLimiter\":false,\"PacketRateLimitIP\":0,\"PacketRateLimitPeerID\":0,\"BytesRateLimitIP\":0,\"BytesRateLimitPeerID\":0,\"RateLimitTolerance\":0,\"BloomFilterMode\":false,\"SoftBlacklistedPeerIDs\":null,\"EnableConfirmations\":false},\"WakuV2Config\":{\"Enabled\":true,\"Host\":\"0.0.0.0\",\"Port\":0,\"LightClient\":true,\"FullNode\":false,\"DiscoveryLimit\":20,\"DataDir\":\"\",\"MaxMessageSize\":0,\"EnableConfirmations\":false,\"CustomNodes\":{},\"PeerExchange\":false,\"Nameserver\":\"\",\"EnableDiscV5\":true,\"UDPPort\":0,\"AutoUpdate\":true,\"EnableStore\":false,\"StoreCapacity\":0,\"StoreSeconds\":0,\"TelemetryServerURL\":\"\",\"EnableMissingMessageVerification\":true,\"EnableStoreConfirmationForMessagesSent\":false},\"BridgeConfig\":{\"Enabled\":false},\"ShhextConfig\":{\"PFSEnabled\":true,\"InstallationID\":\"8712b338-9a00-496b-92d4-8b6a8c53eb1f\",\"MailServerConfirmations\":true,\"EnableConnectionManager\":false,\"EnableLastUsedMonitor\":false,\"ConnectionTarget\":0,\"RequestsDelay\":0,\"MaxServerFailures\":0,\"MaxMessageDeliveryAttempts\":3,\"WhisperCacheDir\":\"\",\"DisableGenericDiscoveryTopic\":false,\"SendV1Messages\":false,\"DataSyncEnabled\":true,\"VerifyTransactionURL\":\"***\",\"VerifyENSURL\":\"***\",\"VerifyENSContractAddress\":\"0x00000000000C2E074eC69A0dFb2997BA6C7d2e1e\",\"VerifyTransactionChainID\":5,\"DefaultPushNotificationsServers\":null,\"AnonMetricsSendID\":\"\",\"AnonMetricsServerEnabled\":false,\"AnonMetricsServerPostgresURI\":\"\",\"BandwidthStatsEnabled\":false},\"WalletConfig\":{\"Enabled\":true,\"StatusProxyEnabled\":false,\"EnableCelerBridge\":false},\"LocalNotificationsConfig\":{\"Enabled\":true},\"BrowsersConfig\":{\"Enabled\":true},\"PermissionsConfig\":{\"Enabled\":true},\"MailserversConfig\":{\"Enabled\":true},\"Web3ProviderConfig\":{\"Enabled\":false},\"ConnectorConfig\":{\"Enabled\":false},\"SwarmConfig\":{\"Enabled\":false},\"TorrentConfig\":{\"Enabled\":false,\"Port\":0,\"DataDir\":\"/data/user/0/im.status.ethereum.pr/no_backup/data/archivedata\",\"TorrentDir\":\"/data/user/0/im.status.ethereum.pr/no_backup/data/torrents\"},\"RegisterTopics\":null,\"RequireTopics\":{},\"MailServerRegistryAddress\":\"\",\"PushNotificationServerConfig\":{\"Enabled\":false,\"Identity\":null,\"GorushURL\":\"\"},\"OutputMessageCSVEnabled\":false,\"ProcessBackedupMessages\":false}" duration=26.861042ms
t=2024-10-21T07:33:01+0000 lvl=dbug msg=callPrivateRPC params="[{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"wakuext_activityCenterNotifications\", duration=44.48625ms

@ilmotta
Copy link
Contributor

ilmotta commented Oct 21, 2024

Look at the time. I would expect wakuext_chatsPreview to be invoked soon after receiving signal node.login, but actually it isn't. It gets delayed for around 5-6 seconds. So we should figure out why the delay occurs on the frontend. Could you help take a look?

@qfrank, I can have a look yes, but at the moment, just looking at the code I don't see how the client could be the culprit of the delay.

  1. Client calls endpoint wakuext_startMessenger.
  2. On success immediately dispatches :profile.login/messenger-started.
  3. Immediately runs effect :fetch-chats-preview.
  4. Immediately calls endpoint wakuext_chatsPreview.

I'll verify what's going on and share here 👍🏼

@ilmotta
Copy link
Contributor

ilmotta commented Oct 22, 2024

Look at the time. I would expect wakuext_chatsPreview to be invoked soon after receiving signal node.login, but actually it isn't. It gets delayed for around 5-6 seconds. So we should figure out why the delay occurs on the frontend

@qfrank I double-checked the code again and I'm sure now the reason for the 5-6s delay is caused by the status-go layer. When a signal node.login arrives, the client immediately calls wakuext_startMessenger. This endpoint will call messenger.InitFilters(), which we know is not fast enough yet when it needs to process large communities such as Status (which is the case in the reproduction steps).

This is exactly what I expected from this issue, no? The problem is not really about the message history or how many messages are sent, it's about the time to initialize the messenger. The same root cause of issue #20173. On the client side we already eliminated the freeze to load large communities in #20164. I think all there's left to do is see if we can optimize messenger.InitFilters any further.

Alternative solution

In case we get stuck and can't optimize the Go code, we could initialize filters in steps (as separate goroutines) and send signals to the client as the processing progresses. For example, community chats could be a separate part of the filter initialization, but the part initializing chats from the DB could finish earlier and be processed concurrently. Or another example, the filters for pub keys from contacts could be initialized separately.

This would be a mitigation solution so that users of large communities can see other important data in the app before community filters are established. We could also consider processing communities concurrently to establish community filters (this could alleviate the problem for one of Status' users who is waiting for minutes and is part of multiple communities).

The downside is in terms of complexity on the client to process the messenger initialization using multiple signals, but the upside for the user could be a reduction in perceived latency to load data in the app.

cc @osmaczko @igor-sirotin

@ilmotta ilmotta moved this to In Progress in Status Desktop/Mobile Board Oct 22, 2024
@ilmotta ilmotta added this to the 2.32.0 Beta milestone Oct 22, 2024
@qfrank
Copy link
Contributor

qfrank commented Oct 22, 2024 •
edited
Loading

Thank you for the investigation! But how can we explain the timestamp 🤔

wakuext_startMessenger finished in 1.063248541s, it was logged at 2024-10-21T07:32:54+0000, so it was invoked around at 2024-10-21T07:32:53

then frontend received node.login at 2024-10-21T07:32:53.674Z , so wakuext_chatsPreview should be invoked soon after 2024-10-21T07:32:53.674Z, but it was invoked at t=2024-10-21T07:32:59+0000

maybe we can draft a PR and add some log in frontend to see what the actual time when it start invoking wakuext_chatsPreview and ask @pavloburykh to try the draft PR build ? WDYT? @ilmotta

@qfrank
Copy link
Contributor

qfrank commented Oct 22, 2024 •
edited
Loading

In case we get stuck and can't optimize the Go code, we could initialize filters in steps (as separate goroutines) and send signals to the client as the processing progresses. For example, community chats could be a separate part of the filter initialization, but the part initializing chats from the DB could finish earlier and be processed concurrently. Or another example, the filters for pub keys from contacts could be initialized separately.

This would be a mitigation solution so that users of large communities can see other important data in the app before community filters are established. We could also consider processing communities concurrently to establish community filters (this could alleviate the problem for one of Status' users who is waiting for minutes and is part of multiple communities).

The downside is in terms of complexity on the client to process the messenger initialization using multiple signals, but the upside for the user could be a reduction in perceived latency to load data in the app.

This solution we definitely could try, but currently you can see that wakuext_startMessenger only took around 1 second duration, so I'm more curious how to explain the timestamp ATM, is it because frontend not able to handle the data returned from some specific backend API efficiently or something like that?

@ilmotta
Copy link
Contributor

ilmotta commented Oct 22, 2024 •
edited
Loading

This solution we definitely could try, but currently you can see that wakuext_startMessenger only took around 1 second duration, so I'm more curious how to explain the timestamp ATM, is it because frontend not able to handle the data returned from some specific backend API efficiently or something like that?

Doesn't hurt to ask, but are we sure the duration is calculated correctly?

You can try to comment out the line that calls [:dispatch [:community/fetch]] in the login phase and see if it helps. That's the only event that could have significant overhead of seconds, at least that I can think of. Basically if you were able to reproduce this issue, try to comment out effects in :profile.login/login-existing-profile and check logs.

I see the response from wakuext_startMessenger is a large struct in status-go, but on the client we completely ignore

status-mobile/src/status_im/contexts/profile/login/events.cljs

Line 133 in 020d5cc

(fn [{:keys [db]} [_]]
. Consider passing :js-response true to the place calling wakuext_startMessenger because otherwise the effect :json-rpc/call will automatically transform the response as CLJS data, but we don't need that.

Edit: adding :js-response true to can also significantly reduce freezes in lower end devices. Might be one of the reasons for freezes in #20283

status-mobile/src/status_im/contexts/profile/login/events.cljs

Line 56 in 020d5cc

[{:method "wakuext_startMessenger"

@qfrank qfrank mentioned this issue Nov 18, 2024
Open
@ilmotta ilmotta linked a pull request Nov 20, 2024 that will close this issue
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@qfrank qfrank

Labels
mobile-core performance
Projects
Status Desktop/Mobile Board
Status: In Progress
Milestone
2.32.0
Development

Successfully merging a pull request may close this issue.

perf: Optimize messenger initialization status-im/status-mobile
3 participants
@ilmotta @qfrank @mariia-skrypnyk