Android app UI is slow when recieving new messages

[flexsurfer]

Bug Report

Problem

When i open app UI is slow. Sometimes it's slow during using it

Expected behavior

UI is smooth

Investigations

Updated 5 Mar 2020

• 1) dispatch-later is paused when app in background, use :utils/dispatch-later instead
• 2) it seems after a long time in background :utils/dispatch-later works differently as well (not proved technically, only visually)
• 3) dispatch-later with 20ms leads to subs and views recalculations, if dispatch is used, subs recalculated only once , dispatch-later should be replaced by another approach
• 4) parametrized subscriptions leads to a lot of computations when app-db is changed, do not use them
• 5) subscriptions usage is not optimized, shouldn't be used in chat views at all, currently, we recalculate all data for every message, message should be added in event, subscription must only return the result without recalculating data
• 6) process-response signal is to often, probably we should send it not more than once a second
• 7) move all data modification to status-go, currently, we recalculate timestamps for all messages in subscription when receiving every new message
• 8) cljs-bean should be used only when you want to access js object , not when you want to modify this data
• 9) in flat-list new array is created each time data is changed

ideal implementation

status-go signals json with new data -> status-react converts json to js, and append data to js array , js array is set to flat-list directly, no cljs data or subscriptions involved

[flexsurfer]

also i can see this in the logs

{"type":"messages.new","event":{"contacts":[{"id":"0x04c656416d5a3733ac1e7a3cebfa5dd7e0316c9283a9e112cf46643dea4f73dc671e2d5102bd7ad4dd5f004767e83a7f099dbd0229e77099d52878106fa83151b7","name":"dmyang.stateofus.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Farflung Thunderous Azurevasesponge","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null},
                                            {"id":"0x04934e6a3bc98c889d7b4550ae6d4dee305a990b2db756724b216bc39469af20ae06df23acebcd307551e2ba56c69e6a1db47f3673195a98eeefcdcc53578176e8","name":"mathias.stateofus.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Silver Palegoldenrod Chihuahua","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null},
                                            {"id":"0x045a705941ed43ce37f87337049ff4696a5d72c419a45b553941e157f1a68f582bd4bec46f113f906b2c90e495e982aad19f101603d49722d061d14de1579ccc60","name":"pantsme.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Lighthearted Harsh Antarcticfurseal","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null},
                                            {"id":"0x046562b45bf066e388a8859cd6f3faa3e939dc4129bc672e831ab522e86fffd0fbfb59f6ed89ee500a0a7bf609e6ede0956fde967c6c6a1b9868c56c2d2a8cc52c","name":"saxis.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Hungry Bronze Koodoo","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null},
                                            {"id":"0x04f1a4b58b7e25eb4aa5ef50ff92ff4078dc066edc5da38c72509d3930411186fec468ba4d96daf2165c7c88c04decd3ec3cb9fad2e893592a856cb61497d8a1d7","name":"jjjj.stateofus.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Fabulous Sophisticated Kitfox","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null},
                                            {"id":"0x04590fd012ecbb5c4565f95838094a3779a26a2af46eba855a84bdce8128214a558db20d2128d5b90627bd1b54d856a8caaf51b10ad45fe9c5050064398dad6794","name":"tivan0.stateofus.eth","ensVerified":false,"ensVerifiedAt":1583162742,"lastENSClockValue":0,"ensVerificationRetries":0,"alias":"Shiny Infamous Boto","identicon":"data:image/png;base64,","lastUpdated":0,"systemTags":null,"deviceInfo":null}]}}

[flexsurfer]

after i removed filters for contacts , app is much responsive but still when i see in logs :status-im.transport.message.core/process app is slow

[flexsurfer]

so there are two issues:

1. we use :dispatch-later which uses setTimeout https://github.com/day8/re-frame/blob/accc559010c8635020fb929f1a4b081b69f58d5f/src/re_frame/interop.cljs#L38, but RN pauses setTimeout in the background, so when app is opened from the background all handlers called altogether and this slowdown app depends on how long it was in the background

2. process-response function is slow, when it's called UI is slow , why ?

[flexsurfer]

3. why app always receives the same ens names every 30s? it should receive only new ens names which have been resolved

[flexsurfer]

03-02 20:52:21.055 26669 26718 I ReactNativeJS: contact #js {:id 0x044d7cffa7800a8a79e56819d56b9e651996078b20d3c932e274d1d1b714e1e6c73a5116695bbc690e10a705273619dcb9cb3fb42ab1dbecbfa076145707a62e69, :name syro.stateofus.eth, :ensVerified false, :ensVerifiedAt 1583178738, :lastENSClockValue 0, :ensVerificationRetries 0, :alias Excitable Attractive Wombat, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAnElEQVR4nOzW0QmDMBRA0bZklq7RoTqHQ7mGy8RfMWK8Jur7uOdTJFwehJeUc37F83k6YJtZhFmEWYRZRGo/Yhin1Zf/79t4ZtBpmUWYRbz331u9bhk9J+i0zCLMIvBOLO/UFYJOyyzCLKKyE0vnbiLdpEGnZRZhFlHZiUdelb3+WQo6LbMIswi8E+8RdFpmEWYRZhFmEXMAAAD//zfqI4ZJZpxpAAAAAElFTkSuQmCC, :lastUpdated 0, :systemTags nil, :deviceInfo nil}
03-02 20:52:21.075 26669 26718 I ReactNativeJS: "Elapsed time: 37.000000 msecs"
03-02 20:52:21.095 26669 26718 D ReactNativeJS: DEBUG [status-im.utils.handlers:32] - Handling re-frame event:  :status-im.transport.message.core/process
03-02 20:52:21.101 26669 26718 I ReactNativeJS: contact #js {:id 0x04ff25f516aaf8d45f56e88f415861d2d8bee0854a947001102be0f2184e3e6254211def9e7880c61816a5d4316037a5a599e2f13d8e42d8b91d3431b08f51873b, :name ling.stateofus.eth, :ensVerified false, :ensVerifiedAt 1583178738, :lastENSClockValue 0, :ensVerificationRetries 0, :alias Brief Meager Orangutan, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAfUlEQVR4nOzYwQmAMAxAUZXM4hgu5Rwu5RguE+8iyi+F5vDfsbTwySk0MnOqZxkd8M4swizCLMIsIuiD4zofJ/u6Ndz5VnRaZhFmEWYRZhFmEWYRZhFmET/baa9dlO6rRadlFmEWYRZhFmEWMfsvD5hFmEWYRZhF3AEAAP//WY4VZNLxTcoAAAAASUVORK5CYII=, :lastUpdated 0, :systemTags nil, :deviceInfo nil}
03-02 20:52:21.116 26669 26718 I ReactNativeJS: "Elapsed time: 19.000000 msecs"
03-02 20:52:21.138 26669 26718 D ReactNativeJS: DEBUG [status-im.utils.handlers:32] - Handling re-frame event:  :status-im.transport.message.core/process
03-02 20:52:21.156 26669 26718 I ReactNativeJS: contact #js {:id 0x04972abc39ef974cde542d3eb3e120fd0976a435d2b9e947b40b7ad7f296a39d41057fb0c7d9ffe7d9a95d80f70e1e0100f262da0cbf32561d3accc5f1bf3f57cf, :name yonayeon.stateofus.eth, :ensVerified false, :ensVerifiedAt 1583178738, :lastENSClockValue 0, :ensVerificationRetries 0, :alias Each Idolized Groundbeetle, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAiElEQVR4nOzXwQmFQAwA0f9la/Fkd9Zhd55sZi0gEh1UzGHedQWHgMRtvfdfPcPXAcfMIswizCLMIlp+vC7bSy+e5jE5LTotswiziL//W4BZhFnEyU6M4paM2+3KM7mi0zKLMIt4YCfe/+6iotMyizCLcCcSZhFmEd4TCbMIswizCLOIPQAA//92px5eHztOpAAAAABJRU5ErkJggg==, :lastUpdated 0, :systemTags nil, :deviceInfo nil}
03-02 20:52:21.174 26669 26718 I ReactNativeJS: "Elapsed time: 25.000000 msecs"
03-02 20:52:21.194 26669 26718 D ReactNativeJS: DEBUG [status-im.utils.handlers:32] - Handling re-frame event:  :status-im.transport.message.core/process
03-02 20:52:21.199 26669 26718 I ReactNativeJS: contact #js {:id 0x0439ec10a2de158bb43655b43aba5556d7916667353930d2f958d95e858f45dc1865d1e12b4ff3ca0b247e70370276524b369203cd70aae0b02c1eca7ddc6690d1, :name bradyskj.stateofus.eth, :ensVerified false, :ensVerifiedAt 1583178738, :lastENSClockValue 0, :ensVerificationRetries 0, :alias Smart Cold Blacklab, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAkElEQVR4nOzXsQmAMBBAUZXMYulyzuFyli4T24CS5AfBK/5rxfA5OIwp5zzFs/wd8M4swizCLMIsItUfH+fVPGLf1k/eKgWdllmEWURjE8e2rOecuqDTMoswi5j98wHMIswi8O2Uft3Gzgk6LbMIs4jGJj717NTYDbYUdFpmEWYR3k4JswizCLMIs4g7AAD//7rQHmTA+xY1AAAAAElFTkSuQmCC, :lastUpdated 0, :systemTags nil, :deviceInfo nil}
03-02 20:52:21.234 26669 26718 I ReactNativeJS: "Elapsed time: 25.000000 msecs"
03-02 20:52:21.2

[flexsurfer]

(fx/merge cofx
                        {:dispatch [::process response-js]}
                        (handle-contact (-> contact (clj-bean/->clj) (data-store.contacts/<-rpc))

takes 37 msecs doesn't look good ?

[flexsurfer]

(fx/merge cofx
                        {:dispatch [::process response-js]}
                        (handle-contact (-> contact (js->clj :keywordize-keys true) (data-store.contacts/<-rpc))

takes 2 msecs

[flexsurfer]

03-03 12:37:53.044  9889  9969 I ReactNativeJS: chats #js {:id status-chinese, :name status-chinese, :color #887af9, :active true, :chatType 2, :timestamp 1583235472735, :lastClockValue 1583235475741, :deletedAtClockValue 0, :unviewedMessagesCount 1, :members nil, :membershipUpdateEvents nil, :lastMessage #js {:id 0x3c86521770e02a1e56f128faee97b890787ef96e6691c5f92ff7521232a4ab3c, :whisperTimestamp 1583235475000, :from 0x04af240688d70642dbffec659d451b147a3fa50be142049be104198469612eb1f38dc190ca3f45737bf5914547a7ee8d4ff4f628d12d23deca69294f46e4842890, :alias Practical Parched Blueandgoldmackaw, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAk0lEQVR4nOzYwQmEMBBA0d0ltWwLW9jWYWG2YDPxbiTJD5HM4b+jKHwGhgFTzvkVz2d1wD2zCLMIswiziEQ/2I798uT//Q28Uxd0WmYRZhGNTSx3agzdzaDTMoswi2hsYs+96+FNfJJZRNCsd/0fxKybWPImzmMWETSrsYmrBJ2WWYRZhFmEWYRZhFmEWcQZAAD//3lgG2IYXKUEAAAAAElFTkSuQmCC, :seen false, :quotedMessage nil, :rtl false, :parsedText #js [#js {:type paragraph, :children #js [#js {:literal 1}]}], :lineCount 0, :text 1, :chatId status-chinese, :localChatId status-chinese, :clock 1583235475741, :replace , :responseTo , :ensName moderator.stateofus.eth, :sticker nil, :commandParameters nil, :timestamp 1583235475741, :contentType 1, :messageType 2}}
03-03 12:37:53.124  9889  9969 I ReactNativeJS: "Elapsed time: 89.000000 msecs"
03-03 12:37:53.132  9889  9969 D ReactNativeJS: DEBUG [status-im.utils.handlers:32] - Handling re-frame event:  :status-im.transport.message.core/process
03-03 12:37:53.165  9889  9969 I ReactNativeJS: messages #js {:id 0x3c86521770e02a1e56f128faee97b890787ef96e6691c5f92ff7521232a4ab3c, :whisperTimestamp 1583235475000, :from 0x04af240688d70642dbffec659d451b147a3fa50be142049be104198469612eb1f38dc190ca3f45737bf5914547a7ee8d4ff4f628d12d23deca69294f46e4842890, :alias Practical Parched Blueandgoldmackaw, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAk0lEQVR4nOzYwQmEMBBA0d0ltWwLW9jWYWG2YDPxbiTJD5HM4b+jKHwGhgFTzvkVz2d1wD2zCLMIswiziEQ/2I798uT//Q28Uxd0WmYRZhGNTSx3agzdzaDTMoswi2hsYs+96+FNfJJZRNCsd/0fxKybWPImzmMWETSrsYmrBJ2WWYRZhFmEWYRZhFmEWcQZAAD//3lgG2IYXKUEAAAAAElFTkSuQmCC, :seen false, :quotedMessage nil, :rtl false, :parsedText #js [#js {:type paragraph, :children #js [#js {:literal 1}]}], :lineCount 0, :text 1, :chatId status-chinese, :localChatId status-chinese, :clock 1583235475741, :replace , :responseTo , :ensName moderator.stateofus.eth, :sticker nil, :commandParameters nil, :timestamp 1583235475741, :contentType 1, :messageType 2}
03-03 12:37:53.207  9889  9969 I ReactNativeJS: "Elapsed time: 74.000000 msecs"

[flexsurfer]

so process-response should be optimized

[flexsurfer]

03-03 12:48:38.940  9889  9969 I ReactNativeJS: chats #js {:id testt, :name testt, :color #887af9, :active true, :chatType 2, :timestamp 1583236118722, :lastClockValue 1583236118121, :deletedAtClockValue 0, :unviewedMessagesCount 7, :members nil, :membershipUpdateEvents nil, :lastMessage #js {:id 0xcab1ab9a5b39981db9eda8e7bf2dd0468cd8a79bf995ba68ec7efb48fa02d70a, :whisperTimestamp 1583236118000, :from 0x045eb8de981800d376397371421171619edabafde23bbe868746f996258674ce8e73afc3c30691838ffecb3b2cb90057324f2e8fd631d705c71ee8024db95440e6, :alias Authorized Skyblue Puppy, :identicon data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAADIAAAAyCAIAAACRXR/mAAAAmElEQVR4nOzXsQ2DMBBAUUCehY2YhDmYhI1YxrQWRtjfDVf8VyZK8nXS6ULKOU/xLH8HvDOLMIswizCLSN9vH9f5eGVft4Gfod8TdFpmEWYRs/+3ALMIs4jGTazV160HvaRBp2UWYRbRuIk9e1dv2dinSkGnZRZhFoFvYs/eje1mKei0zCLMInxOJMwizCLMIswi7gAAAP//gXwhXutx4EUAAAAASUVORK5CYII=, :seen false, :quotedMessage nil, :rtl false, :parsedText #js [#js {:type paragraph, :children #js [#js {:literal Test}]}], :lineCount 0, :text Test, :chatId testt, :localChatId testt, :clock 1583236118121, :replace , :responseTo , :ensName , :sticker nil, :commandParameters nil, :timestamp 1583236118121, :contentType 1, :messageType 2}}
03-03 12:48:38.949  9889  9969 I ReactNativeJS: "Elapsed time: 15.000000 msecs"

[flexsurfer]

hm one thought about dispatch-later is that it visible when there are heavy computations in views and subs, but if we use dispatch we have these calculations only once when all dispatches are handled
but with dispatch-later views and subs recalculated and re-render each time for every event
yeah that looks reasonable at least
we need to take all events, subs and views under full control and add performance monitoring in e2e tests
for events and views its easy to do, for subs we need some changes

[flexsurfer]

i feel like using subscriptions for chat view is kinda wrong ?
and this thing also bothers me https://github.com/status-im/status-react/blob/f3df8b2ec89f8403d2eb81e9e10859b0d783e9ef/src/status_im/ui/components/list/views.cljs#L218
and things like this https://github.com/status-im/status-react/blob/f5488e1f61eb87c374a23a357d057a624a642e46/src/status_im/subs.cljs#L825
so for every new message we recalculate lots of things and create new js array ? mhm doesn't look good

[flexsurfer]

parametrised subscriptions doesn't look good, like https://github.com/status-im/status-react/blob/f5488e1f61eb87c374a23a357d057a624a642e46/src/status_im/subs.cljs#L850 and https://github.com/status-im/status-react/blob/f5488e1f61eb87c374a23a357d057a624a642e46/src/status_im/subs.cljs#L1663
because they duplicate subscriptions
and last one doesn't look good because we call status-go inside subscription , brrrr

[flexsurfer]

worst case with background and contacts signal have been fixed, so I updated description and removed high priority and release labels

[flexsurfer]

again UI freezing once per 30s on Android

[flexsurfer]

separate issue for contacts #10287

[churik]

@flexsurfer is this issue still relevant?

[flexsurfer]

yes

[churik]

@flexsurfer relevant? :)

[flexsurfer]

yes

[cammellos]

@flexsurfer I will be moving this to a discussion, I think each item probably needs to be addressed separately and we want to drill a bit more down on it. We can create separate issue for each point that we agree on.
Thanks