Closed
Bug 1041303
Opened 10 years ago
Closed 10 years ago
[Tarako][SMS][Notification] Long delay between tapping the new SMS notification in utility tray and displaying the SMS
Categories
(Firefox OS Graveyard :: Gaia::Cost Control, defect)
Tracking
(blocking-b2g:1.3T+, b2g-v1.3T fixed)
People
(Reporter: wchang, Assigned: dwi2)
References
Details
Attachments
(3 files, 1 obsolete file)
try some different STRs:
1. Receive multiple SMS's from the same number
2. Wait until all notifications have sounded
3. Open utility tray and tap on the new SMS notification
OR
1. Have some app running in the foreground e.g. music
2. Receive a SMS
3. Open utility trap and tap on the new SMS notification
In both cases, on Tarako the time it takes from tapping the notification to the thread being displayed is long, sometimes up to 4~5 seconds.
Reporter | ||
Comment 1•10 years ago
|
||
Mike,
Not sure if this comes from the new mechanism you introduced in bug 995907, can you see if it's possible to improve?
Maybe allowing the sms app to remain in the background after a notification if device memory allows?
Steve,
If possible can you check also in parallel to buy some time?
Apologies to the urgent request, we're at the partner's site now and this problem is quite prominent so it would be great to get some insights here.
1.3T+ to get some traction, will adjust according to feedback/findings.
blocking-b2g: --- → 1.3T+
Flags: needinfo?(schung)
Flags: needinfo?(mhenretty)
Comment 2•10 years ago
|
||
Let me guess, the time it took is probably bug 1041270 (cold launch time of Message app) + the time takes for system message to be dispatched.
Please add some log to verify that.
Comment 4•10 years ago
|
||
Per bug 1041270 comment 3, it seems if cost control app doesn't work aggressively, then Message app can be launched faster. Let's do this first, and see if we can find another significant cause.
Comment 6•10 years ago
|
||
(Moving the component to Cost Control for now.)
Component: Gaia::SMS → Gaia::Cost Control
Comment 7•10 years ago
|
||
Comment 8•10 years ago
|
||
attachment 8459430 [details] STRs:
1. Receive multiple SMS's from the same number
2. Wait until all notifications have sounded
3. Open utility tray and tap on the new SMS notification
Updated•10 years ago
|
Attachment #8459430 -
Attachment mime type: text/x-log → text/plain
Assignee | ||
Comment 9•10 years ago
|
||
I made two approach. This is approach 1:
Prevent usage app from starting up at three moments:
1. Utility tray show up
2. Receive incoming SMS
3. Call ended
Attachment #8459436 -
Flags: review?(ehung)
Flags: needinfo?(tzhuang)
Assignee | ||
Comment 10•10 years ago
|
||
This is approach 2, totally remove Usage app in production and engineering build.
Attachment #8459437 -
Flags: review?(ehung)
Assignee | ||
Updated•10 years ago
|
Attachment #8459436 -
Attachment description: pr to v1.3t → approach 1, pr to v1.3t
Comment 11•10 years ago
|
||
(In reply to Tzu-Lin Huang [:dwi2][:tzhuang] from comment #10)
> Created attachment 8459437 [details] [review]
> approach 2, pr to v1.3t
>
> This is approach 2, totally remove Usage app in production and engineering
> build.
No, we will keep it in the build. so I won't review this.
Updated•10 years ago
|
Attachment #8459437 -
Flags: review?(ehung)
Comment 12•10 years ago
|
||
Comment on attachment 8459436 [details] [review]
approach 1, pr to v1.3t
We need a product decision on removing "sms-received" and "telephony-call-ended". If we do that, service provider lose a chance to send message or pop-up a dialog for notifying the user that he/she is reaching the Usage level.
Reporter | ||
Comment 13•10 years ago
|
||
Thanks Evelyn,
Is that what the listening is for? Any other feature impacts?
Marvin, I'll discuss with you offline about this before you get back to Evelyn.
(In reply to Evelyn Hung [:evelyn] from comment #12)
> Comment on attachment 8459436 [details] [review]
> approach 1, pr to v1.3t
>
> We need a product decision on removing "sms-received" and
> "telephony-call-ended". If we do that, service provider lose a chance to
> send message or pop-up a dialog for notifying the user that he/she is
> reaching the Usage level.
Flags: needinfo?(wchang)
Comment 14•10 years ago
|
||
Hi Wayne, I could only see a serious delay when music is playing at foreground. In this case, cpu will reach up to 80 or even 90%, notification event dispatched by system message will have tremendous delay[1] while cpu is high(some other action will also got penalty the high cpu usage, like app getself or even mobile message API). When we move the music app to background, the cpu will drop to ~10% and all latency for every action could be reduced to half. So maybe we can propose to move foreground app to background when system need to handle notification event.
[1] The details for the delay:
|no music | music playing at forground | playing at background
Notification clicked to | | |
system message received | 1~2 sec | 4~5 sec | 2~3 sec
-----------------------------------------------------------------------------------------
App getself to onsuccess| | |
return | 90 ms | 900~1000 ms | 150~170 ms
-----------------------------------------------------------------------------------------
mobileMessage api | | |
(getMessage) | 100 ms | 400~500 ms | 100~300 ms
Flags: needinfo?(schung)
Comment 15•10 years ago
|
||
(In reply to Wayne Chang [:wchang] from comment #0)
> try some different STRs:
>
> 1. Receive multiple SMS's from the same number
> 2. Wait until all notifications have sounded
> 3. Open utility tray and tap on the new SMS notification
Add more descriptions for case 1.
At step 3, we open utility tray and tap on new SMS notification, then we will stay at homescreen for a while (3~4 seconds), finally SMS application launched and load time is 500~800ms.
Partner is complaining about why does it stay at homescreen for a long time.
Assignee | ||
Comment 16•10 years ago
|
||
Hi Wayne,
"sms-received" in usage app is for listening to 'balance' SMS, which tells user's account balance. This only works on some specific operators. (I can list the names to you in private). And listening to "telephony-call-end" will trigger device to send a balance requesting SMS to operator. This works on prepaid card of the same specific operators as "sms-received" ones.
Assignee | ||
Updated•10 years ago
|
Attachment #8459437 -
Attachment is obsolete: true
Comment 17•10 years ago
|
||
(In reply to Steve Chung [:steveck] from comment #14)
> Hi Wayne, I could only see a serious delay when music is playing at
> foreground. In this case, cpu will reach up to 80 or even 90%, notification
> event dispatched by system message will have tremendous delay[1] while cpu
> is high(some other action will also got penalty the high cpu usage, like app
> getself or even mobile message API). When we move the music app to
> background, the cpu will drop to ~10% and all latency for every action could
> be reduced to half. So maybe we can propose to move foreground app to
> background when system need to handle notification event.
>
> [1] The details for the delay:
> |no music | music playing at forground | playing at
> background
> Notification clicked to | | |
> system message received | 1~2 sec | 4~5 sec | 2~3 sec
> -----------------------------------------------------------------------------
> ------------
> App getself to onsuccess| | |
> return | 90 ms | 900~1000 ms | 150~170 ms
> -----------------------------------------------------------------------------
> ------------
> mobileMessage api | | |
> (getMessage) | 100 ms | 400~500 ms | 100~300 ms
Thanks Steve. So per his observation, system message will have tremendous delay while music is playing. We need a Gecko dev's help to check if we can improve the time of message dispatching.
Thinker, If someone in your team could investigate a bit more on system message, that will be very helpful.
Flags: needinfo?(tlee)
Comment 18•10 years ago
|
||
One more observation: when messages are coming, launch sms app via app icon won't have the delay. So we are sure the delay is caused by system message.
Assignee | ||
Comment 19•10 years ago
|
||
I've add some debug log to observe where delay comes from. (https://github.com/dwi2/gaia/commit/981bb573e5a422578df58b32ec276d15d4b92c67)
I did the experiment while music is playing at background and receive 3 incoming SMS.
log (observation inline):
E/GeckoConsole( 4929): Content JS LOG at app://system.gaiamobile.org/js/app_window_factory.js:52 in awf_handleEvent: [1041303]<1405946195337> open-app: {"url":"app://sms.gaiamobile.org/index.html","manifestURL":"app://sms.gaiamobile.org/manifest.webapp","isActivity":false,"onlyShowApp":false,"showApp":false,"expectingSystemMessage":true}
E/GeckoConsole( 4929): Content JS LOG at app://system.gaiamobile.org/js/notifications.js:244 in ns_tap: [1041303]<1405946195441> mozContentEvent: desktop-notification-click, id = app-notif-{0f42cbca-8d2f-4d65-bdad-9f1ef64b3955}
// This is where user tap notification in utility tray, at time 1405946195441 (in ms)
E/GeckoConsole( 4929): Content JS LOG at app://system.gaiamobile.org/js/app_window_factory.js:52 in awf_handleEvent: [1041303]<1405946195476> open-app: {"url":"app://sms.gaiamobile.org/index.html","manifestURL":"app://sms.gaiamobile.org/manifest.webapp","isActivity":false,"onlyShowApp":false,"showApp":false,"expectingSystemMessage":true}
// system got 'open-app' for SMS, start to load SMS app for incoming notification, at time 1405946195476
E/GeckoConsole(15303): Content JS LOG at app://sms.gaiamobile.org/gaia_build_defer_index.js:675 in ActivityHandler.init: [1041303]<1405946198544> just before mozSetMessageHandler notification
// SMS finish register message handler for notification at time 1405946198544
E/GeckoConsole(15303): Content JS LOG at app://sms.gaiamobile.org/gaia_build_defer_index.js:696 in ah_onNotificationClick: [1041303]<1405946199139> SMS app got notification of {"clicked":true,"title":"+886978725125","body":"Rtyffg","imageURL":"app://sms.gaiamobile.org/style/icons/Sms_60.png?threadId=1&number=%2B886978725125&id=5"}
E/GeckoConsole(15303): Content JS LOG at app://sms.gaiamobile.org/gaia_build_defer_index.js:696 in ah_onNotificationClick: [1041303]<1405946199244> SMS app got notification of {"clicked":false,"title":"+886978725125","body":"Rtyffg","imageURL":"app://sms.gaiamobile.org/style/icons/Sms_60.png?threadId=1&number=%2B886978725125&id=5"}
E/GeckoConsole( 4929): Content JS LOG at app://system.gaiamobile.org/js/app_window_factory.js:45 in awf_handleEvent: [1041303]<1405946199468> webapps-launch: {"timestamp":1405946199449,"url":"app://sms.gaiamobile.org/index.html","manifestURL":"app://sms.gaiamobile.org/manifest.webapp"}
E/GeckoConsole(15303): Content JS LOG at app://sms.gaiamobile.org/gaia_build_defer_index.js:681 in act_action: [1041303]<1405946199976> show
E/GeckoConsole(15303): Content JS LOG at app://sms.gaiamobile.org/gaia_build_defer_index.js:696 in ah_onNotificationClick: [1041303]<1405946200050> SMS app got notification of {"clicked":false,"title":"+886978725125","body":"Jkgfgh","imageURL":"app://sms.gaiamobile.org/style/icons/Sms_60.png?threadId=1&number=%2B886978725125&id=6"}
From the log, the biggest delay is between System got 'open-app' event and SMS finished message handler registration, which is about 3 seconds.
So the delay seems to be coming from SMS app loading time.
Comment 20•10 years ago
|
||
Hey Tzu-Lin, thanks for helping the profiling. I just insert some logs in system side and you are right about the bottleneck, the app load time. Although the system message also got some delay in this case, it's trivial comparing to the app load time. The loading time takes 1~2 sec and up to 5 sec or more when music in the foreground. But please note it's a generic issue because I could reproduce same behavior with email notification. Considering the addition event communication time for notification system message, it's not far away from the app cold launch time. The difference is splash screen will display first for app cold launch case. Maybe we could also utilize splash screen here to let user realizes about the app is loading actually. About the music playing at foreground case, I've left my thought in comment 14.
Assignee | ||
Comment 21•10 years ago
|
||
I made a WIP workaround, which directly launch SMS app while user click notification on utility tray.
This workaround partially bypass the route of notification system message sent to SMS app and provide better user experience. Immediately after clicking, user will see SMS splash instead of Homescreen app. Although we still need 3 seconds or so to launch SMS app.
I flag Evelyn and Steve for feedback before I move on.
Attachment #8459668 -
Flags: feedback?(schung)
Attachment #8459668 -
Flags: feedback?(ehung)
Comment 22•10 years ago
|
||
(In reply to Wayne Chang [:wchang] from comment #1)
> Mike,
> Not sure if this comes from the new mechanism you introduced in bug 995907,
> can you see if it's possible to improve?
>
> Maybe allowing the sms app to remain in the background after a notification
> if device memory allows?
Just for backround, my patch created an entry point in the sms app that loads only the javascript necessary for handling an sms-received system message (which fires the notification), and then immediately closes the app. Wayne is referring to the fact that this ensures we always have a cold-launch of sms when clicking the notification. However, given the memory constraints of the device, the sms app app would not stick around for long anyway in the case of playing video/music (in fact before my patch it was being OOM'd before even firing the notification). I think regardless we will need to fix the case of the slow sms notification system message handler.
Flags: needinfo?(mhenretty)
Comment 23•10 years ago
|
||
It seems like a launch time issue.
For comment 19, Tzu-Lin, could you provide a complete log?
Flags: needinfo?(tlee) → needinfo?(tchou)
Comment 24•10 years ago
|
||
Tzu-Lin and I just try another method, which handles system message in another js and loads it at first for launching message app ASAP. But it didn't work as we expected anyway. Loading the first script for setting system message handler still took nearly 2 sec from tapping the notification. It only reduced 400~500ms comparing to set the handler after load event. The latency also increases while music playing in foreground, which might even triple the loading time only for the waiting the first file loaded. So the bottleneck is in app loading time(from window got open-app event to loading app's script), and it's quite sensitive to the cpu usage.
Comment 25•10 years ago
|
||
Comment on attachment 8459668 [details] [review]
approach 3, pr to v1.3t
For the message POV, the possible regression is thread list view will display at first, then switch to the conversation view when system message is received. user will have chance to access any elements while in thread list view, so we might need to disable any pointer events before switching to conversation. Not sure whether we need to deal this only for message app(it looks tricky if we only hard-coded for message app), but you will definitely need Alive's feedback if we really want to take this workaround.
Attachment #8459668 -
Flags: feedback?(schung)
Updated•10 years ago
|
status-b2g-v1.3T:
--- → affected
Comment 26•10 years ago
|
||
I've tried the patch in comment 21
attachment 8459668 [details] [review]
approach 3, pr to v1.3t
With 500 messages in sms and music play in foreground,it seems faster than before.
Enable "show time to load" in setting app,the cold launch time for sms is 1748,when 1748 displays,the sms still stays in a black screen.So I record the time by using stopwatch,the time is 3620.
Comment 27•10 years ago
|
||
Correct the NI of comment 23 for Tzu-Lin.
Flags: needinfo?(tchou) → needinfo?(tzhuang)
Comment 28•10 years ago
|
||
I also add some logs in system and find that the mozbrowserloadend event triggered twice with the WIP,the time from first trigger to second trigger cost nearly 2 seconds.
I wonder why there are twice mozbrowserloadend event trigger?Thank you.
07-22 15:50:45.378 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:1013 in windowLauncher: leona,WindowManager windowLauncher
07-22 15:50:45.388 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:624 in setDisplayedApp: leona,setDisplayedApp
07-22 15:50:45.388 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:389 in openWindow: leona windowManager openWindow
07-22 15:50:45.388 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:1013 in windowLauncher: leona,WindowManager windowLauncher
07-22 15:50:45.388 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:1013 in windowLauncher: leona,WindowManager windowLauncher
07-22 15:50:46.088 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:428 in startOpeningTransition: leona transitionOpenCallback
07-22 15:50:46.638 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:201 in frameAnimationend: leona windowManager animationend
07-22 15:50:46.638 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:201 in frameAnimationend: leona windowManager animationend
07-22 15:50:46.638 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:279 in windowOpened: leona windowOpened
07-22 15:50:46.648 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:596 in appLoadedHandler: leona appLoadedHandler,e.type=appopen
07-22 15:50:47.858 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:596 in appLoadedHandler: leona appLoadedHandler,e.type=mozbrowserloadend
07-22 15:50:47.858 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:358 in loadend: leona,windowManager loadend
//Here nearly cost 2 seconds from the first appLoadedHandler to the second appLoadedHandler
07-22 15:50:49.548 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:596 in appLoadedHandler: leona appLoadedHandler,e.type=mozbrowserloadend
07-22 15:50:49.548 E/GeckoConsole( 5099): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:358 in loadend: leona,windowManager loadend
07-22 15:50:49.658 E/GeckoConsole( 5334): Content JS LOG at app://sms.gaiamobile.org/js/startup.js:49 in anonymous: leona->sms startup.js load
07-22 15:50:49.658 E/GeckoConsole( 5334): Content JS LOG at app://sms.gaiamobile.org/js/startup.js:10 in localized: leona->startup.js localized
Assignee | ||
Comment 29•10 years ago
|
||
Comment on attachment 8459668 [details] [review]
approach 3, pr to v1.3t
Hi Steve,
I've modify the patch as you mentioned in comment 25. Please kindly help to review the patch, thanks
Hi Alive,
Please help to review the System app part, many thanks.
This patch is exclusively for v1.3t only.
Attachment #8459668 -
Flags: review?(schung)
Attachment #8459668 -
Flags: review?(alive)
Updated•10 years ago
|
Attachment #8459668 -
Flags: review?(alive) → review+
Comment 30•10 years ago
|
||
(In reply to Tzu-Lin Huang [:dwi2][:tzhuang] from comment #29)
> Comment on attachment 8459668 [details] [review]
> approach 3, pr to v1.3t
>
> Hi Steve,
>
> I've modify the patch as you mentioned in comment 25. Please kindly help to
> review the patch, thanks
>
Reply some comments on github, please adjust the timing for disabling the pointer event, thanks!
Comment 31•10 years ago
|
||
(In reply to Evelyn Hung [:evelyn] from comment #12)
> Comment on attachment 8459436 [details] [review]
> approach 1, pr to v1.3t
>
> We need a product decision on removing "sms-received" and
> "telephony-call-ended". If we do that, service provider lose a chance to
> send message or pop-up a dialog for notifying the user that he/she is
> reaching the Usage level.
Hi Tzu-Lin, could you help to update the patch and let Evelyn to review again?
We would like to land both approach 1 and approach 3. thank you very much.
Reporter | ||
Comment 32•10 years ago
|
||
(In reply to Tzu-Lin Huang [:dwi2][:tzhuang] from comment #9)
> Created attachment 8459436 [details] [review]
> approach 1, pr to v1.3t
>
> I made two approach. This is approach 1:
> Prevent usage app from starting up at three moments:
> 1. Utility tray show up
> 2. Receive incoming SMS
> 3. Call ended
Tzu-lin, Danny's comment 31 should say -
In approach 1 you described, let's not touch the event listeners so the user can still receive warning they set. However, let's remove the utility tray widget and make sure it doesn't wake up everytime user checks for notifications.
Approach 3 showed great improvement, thank you very much.
Marvin, FYI for product info
Assignee | ||
Comment 33•10 years ago
|
||
Comment on attachment 8459436 [details] [review]
approach 1, pr to v1.3t
Hi Evelyn,
Per comment 30 and comment 31, please help to review the patch again.
Thanks
Attachment #8459436 -
Flags: review?(ehung)
Comment 34•10 years ago
|
||
Comment on attachment 8459436 [details] [review]
approach 1, pr to v1.3t
Thanks!
Attachment #8459436 -
Flags: review?(ehung) → review+
Comment 35•10 years ago
|
||
Comment on attachment 8459668 [details] [review]
approach 3, pr to v1.3t
Only one nit, so r=me and thanks for helping this urgent issue!
Attachment #8459668 -
Flags: review?(schung) → review+
Comment 36•10 years ago
|
||
(In reply to Tzu-Lin Huang [:dwi2][:tzhuang] from comment #33)
> Comment on attachment 8459436 [details] [review]
> approach 1, pr to v1.3t
>
> Hi Evelyn,
> Per comment 30 and comment 31, please help to review the patch again.
>
> Thanks
Thanks, Tzhuang. Are you the one who could be the owner for this bug? Thanks.
Updated•10 years ago
|
Assignee: nobody → tzhuang
Assignee | ||
Comment 37•10 years ago
|
||
Approach 1 landed on v1.3t
https://github.com/mozilla-b2g/gaia/commit/811cdec039d8b5d0b07a4803dd6eb56f98607569
Approach 3 landed on v1.3t
https://github.com/mozilla-b2g/gaia/commit/72444027ab1beb00a2d2d32d27f08159391b4d77
Comment 38•10 years ago
|
||
clear my ni here, let me know should i need to make any call here.
Flags: needinfo?(mkhoo)
Assignee | ||
Comment 39•10 years ago
|
||
Let's track the long cold launch time at bug 1040020. I'll close this one.
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(tzhuang)
Resolution: --- → FIXED
Updated•10 years ago
|
Attachment #8459668 -
Flags: feedback?(ehung)
Comment 40•10 years ago
|
||
Our QA report a bug, we can't enter data usage app in status bar with this patch, Evelyn and Tzu-Lin, can you check it?
Assignee | ||
Comment 41•10 years ago
|
||
According to comment 32, yes, because we remove usage app from utility tray.
(see https://github.com/mozilla-b2g/gaia/commit/811cdec039d8b5d0b07a4803dd6eb56f98607569)
If your QA have concern to it, then we probably should back it out.
Updated•10 years ago
|
Comment 42•10 years ago
|
||
(In reply to Tzu-Lin Huang [:dwi2][:tzhuang] from comment #41)
> According to comment 32, yes, because we remove usage app from utility tray.
> (see
> https://github.com/mozilla-b2g/gaia/commit/
> 811cdec039d8b5d0b07a4803dd6eb56f98607569)
>
> If your QA have concern to it, then we probably should back it out.
Tzu-Lin, can you revert this change only? Does it impact SMS performance?
Updated•10 years ago
|
Flags: needinfo?(tzhuang)
Reporter | ||
Comment 43•10 years ago
|
||
James,
Displaying usage app in status bar will cause usage app to be activated every time notification tray is open, so we decided to not display the notification widget in order to reduce the system load when the user is going for the sms notification.
Flags: needinfo?(james.zhang)
You need to log in
before you can comment on or make changes to this bug.
Description
•