Closed Bug 1041303 Opened 6 years ago Closed 6 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, critical)

ARM
Gonk (Firefox OS)
defect
Not set
critical

Tracking

(blocking-b2g:1.3T+, b2g-v1.3T fixed)

RESOLVED FIXED
blocking-b2g 1.3T+
Tracking Status
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.
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)
See Also: → 1041270
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.
Duplicate of this bug: 1041270
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.
ni Tzu-lin for helping on comment 4.
Flags: needinfo?(tzhuang)
See Also: → 1040020
(Moving the component to Cost Control for now.)
Component: Gaia::SMS → Gaia::Cost Control
Attached file sms.log
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
Attachment #8459430 - Attachment mime type: text/x-log → text/plain
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)
Attached file approach 2, pr to v1.3t (obsolete) —
This is approach 2, totally remove Usage app in production and engineering build.
Attachment #8459437 - Flags: review?(ehung)
Attachment #8459436 - Attachment description: pr to v1.3t → approach 1, pr to v1.3t
(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.
Attachment #8459437 - Flags: review?(ehung)
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.
Attachment #8459436 - Flags: review?(ehung)
Flags: needinfo?(wchang)
Flags: needinfo?(mkhoo)
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)
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)
(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.
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.
Attachment #8459437 - Attachment is obsolete: true
(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)
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.
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.
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.
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)
(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)
It seems like a launch time issue.

For comment 19, Tzu-Lin, could you provide a complete log?
Flags: needinfo?(tlee) → needinfo?(tchou)
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 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)
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.
Correct the NI of comment 23 for Tzu-Lin.
Flags: needinfo?(tchou) → needinfo?(tzhuang)
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
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)
Attachment #8459668 - Flags: review?(alive) → review+
(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!
(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.
(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
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 on attachment 8459436 [details] [review]
approach 1, pr to v1.3t

Thanks!
Attachment #8459436 - Flags: review?(ehung) → review+
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+
(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.
Assignee: nobody → tzhuang
clear my ni here, let me know should i need to make any call here.
Flags: needinfo?(mkhoo)
Let's track the long cold launch time at bug 1040020. I'll close this one.
Status: NEW → RESOLVED
Closed: 6 years ago
Flags: needinfo?(tzhuang)
Resolution: --- → FIXED
Attachment #8459668 - Flags: feedback?(ehung)
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?
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.
(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?
Flags: needinfo?(tzhuang)
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)
OK, I'll ask our QA to accept it.
Flags: needinfo?(james.zhang)
clear ni per comment 43 and 44
Flags: needinfo?(tzhuang)
You need to log in before you can comment on or make changes to this bug.