search

status-im / status-mobile

a free (libre) open source, mobile OS for Ethereum
https://status.app
Mozilla Public License 2.0
3.9k stars 988 forks source link

Message history loading takes up to 20 sec #21456

Open mariia-skrypnyk opened 1 week ago

mariia-skrypnyk commented 1 week ago

Bug Report

Follow up of https://github.com/status-im/status-mobile/pull/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

qfrank commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 https://github.com/status-im/status-mobile/pull/20173. On the client side we already eliminated the freeze to load large communities in https://github.com/status-im/status-mobile/pull/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

qfrank commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 https://github.com/status-im/status-mobile/blob/020d5cc1c124f9bd2e8931d5275102a7b093d573/src/status_im/contexts/profile/login/events.cljs#L133. 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 https://github.com/status-im/status-mobile/issues/20283

https://github.com/status-im/status-mobile/blob/020d5cc1c124f9bd2e8931d5275102a7b093d573/src/status_im/contexts/profile/login/events.cljs#L56